1 /*
2 * Copyright (C) 2013-2016 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 <dirent.h>
19 #include <errno.h>
20 #include <fcntl.h>
21 #include <inttypes.h>
22 #include <pthread.h>
23 #include <semaphore.h>
24 #include <signal.h>
25 #include <stdio.h>
26 #include <string.h>
27 #include <sys/types.h>
28 #include <unistd.h>
29
30 #include <string>
31
32 #include <android-base/file.h>
33 #include <android-base/stringprintf.h>
34 #ifdef __ANDROID__ // includes sys/properties.h which does not exist outside
35 #include <cutils/properties.h>
36 #endif
37 #include <gtest/gtest.h>
38 #include <log/log_event_list.h>
39 #include <log/log_properties.h>
40 #include <log/log_transport.h>
41 #include <log/logprint.h>
42 #include <private/android_filesystem_config.h>
43 #include <private/android_logger.h>
44
45 #ifndef TEST_PREFIX
46 #ifdef TEST_LOGGER
47 #define TEST_PREFIX android_set_log_transport(TEST_LOGGER);
48 // make sure we always run code despite overrides if compiled for android
49 #elif defined(__ANDROID__)
50 #define TEST_PREFIX
51 #endif
52 #endif
53
54 #if (!defined(USING_LOGGER_DEFAULT) || !defined(USING_LOGGER_LOCAL) || \
55 !defined(USING_LOGGER_STDERR))
56 #ifdef liblog // a binary clue that we are overriding the test names
57 // Does not support log reading blocking feature yet
58 // Does not support LOG_ID_SECURITY (unless we set LOGGER_LOCAL | LOGGER_LOGD)
59 // Assume some common aspects are tested by USING_LOGGER_DEFAULT:
60 // Does not need to _retest_ pmsg functionality
61 // Does not need to _retest_ property handling as it is a higher function
62 // Does not need to _retest_ event mapping functionality
63 // Does not need to _retest_ ratelimit
64 // Does not need to _retest_ logprint
65 #define USING_LOGGER_LOCAL
66 #else
67 #define USING_LOGGER_DEFAULT
68 #endif
69 #endif
70 #ifdef USING_LOGGER_STDERR
71 #define SUPPORTS_END_TO_END 0
72 #else
73 #define SUPPORTS_END_TO_END 1
74 #endif
75
76 // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
77 // non-syscall libs. Since we are only using this in the emergency of
78 // a signal to stuff a terminating code into the logs, we will spin rather
79 // than try a usleep.
80 #define LOG_FAILURE_RETRY(exp) \
81 ({ \
82 typeof(exp) _rc; \
83 do { \
84 _rc = (exp); \
85 } while (((_rc == -1) && ((errno == EINTR) || (errno == EAGAIN))) || \
86 (_rc == -EINTR) || (_rc == -EAGAIN)); \
87 _rc; \
88 })
89
TEST(liblog,__android_log_btwrite)90 TEST(liblog, __android_log_btwrite) {
91 #ifdef TEST_PREFIX
92 TEST_PREFIX
93 #endif
94 int intBuf = 0xDEADBEEF;
95 EXPECT_LT(0,
96 __android_log_btwrite(0, EVENT_TYPE_INT, &intBuf, sizeof(intBuf)));
97 long long longBuf = 0xDEADBEEFA55A5AA5;
98 EXPECT_LT(
99 0, __android_log_btwrite(0, EVENT_TYPE_LONG, &longBuf, sizeof(longBuf)));
100 usleep(1000);
101 char Buf[] = "\20\0\0\0DeAdBeEfA55a5aA5";
102 EXPECT_LT(0,
103 __android_log_btwrite(0, EVENT_TYPE_STRING, Buf, sizeof(Buf) - 1));
104 usleep(1000);
105 }
106
107 #if (defined(__ANDROID__) && defined(USING_LOGGER_DEFAULT))
popenToString(std::string command)108 static std::string popenToString(std::string command) {
109 std::string ret;
110
111 FILE* fp = popen(command.c_str(), "r");
112 if (fp) {
113 if (!android::base::ReadFdToString(fileno(fp), &ret)) ret = "";
114 pclose(fp);
115 }
116 return ret;
117 }
118
isPmsgActive()119 static bool isPmsgActive() {
120 pid_t pid = getpid();
121
122 std::string myPidFds =
123 popenToString(android::base::StringPrintf("ls -l /proc/%d/fd", pid));
124 if (myPidFds.length() == 0) return true; // guess it is?
125
126 return std::string::npos != myPidFds.find(" -> /dev/pmsg0");
127 }
128
isLogdwActive()129 static bool isLogdwActive() {
130 std::string logdwSignature =
131 popenToString("grep /dev/socket/logdw /proc/net/unix");
132 size_t beginning = logdwSignature.find(" ");
133 if (beginning == std::string::npos) return true;
134 beginning = logdwSignature.find(" ", beginning + 1);
135 if (beginning == std::string::npos) return true;
136 size_t end = logdwSignature.find(" ", beginning + 1);
137 if (end == std::string::npos) return true;
138 end = logdwSignature.find(" ", end + 1);
139 if (end == std::string::npos) return true;
140 end = logdwSignature.find(" ", end + 1);
141 if (end == std::string::npos) return true;
142 end = logdwSignature.find(" ", end + 1);
143 if (end == std::string::npos) return true;
144 std::string allLogdwEndpoints = popenToString(
145 "grep ' 00000002" + logdwSignature.substr(beginning, end - beginning) +
146 " ' /proc/net/unix | " +
147 "sed -n 's/.* \\([0-9][0-9]*\\)$/ -> socket:[\\1]/p'");
148 if (allLogdwEndpoints.length() == 0) return true;
149
150 // NB: allLogdwEndpoints has some false positives in it, but those
151 // strangers do not overlap with the simplistic activities inside this
152 // test suite.
153
154 pid_t pid = getpid();
155
156 std::string myPidFds =
157 popenToString(android::base::StringPrintf("ls -l /proc/%d/fd", pid));
158 if (myPidFds.length() == 0) return true;
159
160 // NB: fgrep with multiple strings is broken in Android
161 for (beginning = 0;
162 (end = allLogdwEndpoints.find("\n", beginning)) != std::string::npos;
163 beginning = end + 1) {
164 if (myPidFds.find(allLogdwEndpoints.substr(beginning, end - beginning)) !=
165 std::string::npos)
166 return true;
167 }
168 return false;
169 }
170
171 static bool tested__android_log_close;
172 #endif
173
TEST(liblog,__android_log_btwrite__android_logger_list_read)174 TEST(liblog, __android_log_btwrite__android_logger_list_read) {
175 #if (defined(__ANDROID__) || defined(USING_LOGGER_LOCAL))
176 #ifdef TEST_PREFIX
177 TEST_PREFIX
178 #endif
179 struct logger_list* logger_list;
180
181 pid_t pid = getpid();
182
183 ASSERT_TRUE(NULL !=
184 (logger_list = android_logger_list_open(
185 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
186 1000, pid)));
187
188 log_time ts(CLOCK_MONOTONIC);
189 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
190 #ifdef USING_LOGGER_DEFAULT
191 // Check that we can close and reopen the logger
192 bool pmsgActiveAfter__android_log_btwrite;
193 bool logdwActiveAfter__android_log_btwrite;
194 if (getuid() == AID_ROOT) {
195 tested__android_log_close = true;
196 pmsgActiveAfter__android_log_btwrite = isPmsgActive();
197 logdwActiveAfter__android_log_btwrite = isLogdwActive();
198 EXPECT_TRUE(pmsgActiveAfter__android_log_btwrite);
199 EXPECT_TRUE(logdwActiveAfter__android_log_btwrite);
200 } else if (!tested__android_log_close) {
201 fprintf(stderr, "WARNING: can not test __android_log_close()\n");
202 }
203 __android_log_close();
204 if (getuid() == AID_ROOT) {
205 bool pmsgActiveAfter__android_log_close = isPmsgActive();
206 bool logdwActiveAfter__android_log_close = isLogdwActive();
207 EXPECT_FALSE(pmsgActiveAfter__android_log_close);
208 EXPECT_FALSE(logdwActiveAfter__android_log_close);
209 }
210 #endif
211
212 log_time ts1(CLOCK_MONOTONIC);
213 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
214 #ifdef USING_LOGGER_DEFAULT
215 if (getuid() == AID_ROOT) {
216 pmsgActiveAfter__android_log_btwrite = isPmsgActive();
217 logdwActiveAfter__android_log_btwrite = isLogdwActive();
218 EXPECT_TRUE(pmsgActiveAfter__android_log_btwrite);
219 EXPECT_TRUE(logdwActiveAfter__android_log_btwrite);
220 }
221 #endif
222 usleep(1000000);
223
224 int count = 0;
225 int second_count = 0;
226
227 for (;;) {
228 log_msg log_msg;
229 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
230 break;
231 }
232
233 EXPECT_EQ(log_msg.entry.pid, pid);
234
235 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
236 (log_msg.id() != LOG_ID_EVENTS)) {
237 continue;
238 }
239
240 android_log_event_long_t* eventData;
241 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
242
243 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
244 continue;
245 }
246
247 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
248 if (ts == tx) {
249 ++count;
250 } else if (ts1 == tx) {
251 ++second_count;
252 }
253 }
254
255 EXPECT_EQ(SUPPORTS_END_TO_END, count);
256 EXPECT_EQ(SUPPORTS_END_TO_END, second_count);
257
258 android_logger_list_close(logger_list);
259 #else
260 GTEST_LOG_(INFO) << "This test does nothing.\n";
261 #endif
262 }
263
264 #if (defined(__ANDROID__) || defined(USING_LOGGER_LOCAL))
print_transport(const char * prefix,int logger)265 static void print_transport(const char* prefix, int logger) {
266 static const char orstr[] = " | ";
267
268 if (!prefix) {
269 prefix = "";
270 }
271 if (logger < 0) {
272 fprintf(stderr, "%s%s\n", prefix, strerror(-logger));
273 return;
274 }
275
276 if (logger == LOGGER_DEFAULT) {
277 fprintf(stderr, "%sLOGGER_DEFAULT", prefix);
278 prefix = orstr;
279 }
280 if (logger & LOGGER_LOGD) {
281 fprintf(stderr, "%sLOGGER_LOGD", prefix);
282 prefix = orstr;
283 }
284 if (logger & LOGGER_KERNEL) {
285 fprintf(stderr, "%sLOGGER_KERNEL", prefix);
286 prefix = orstr;
287 }
288 if (logger & LOGGER_NULL) {
289 fprintf(stderr, "%sLOGGER_NULL", prefix);
290 prefix = orstr;
291 }
292 if (logger & LOGGER_LOCAL) {
293 fprintf(stderr, "%sLOGGER_LOCAL", prefix);
294 prefix = orstr;
295 }
296 if (logger & LOGGER_STDERR) {
297 fprintf(stderr, "%sLOGGER_STDERR", prefix);
298 prefix = orstr;
299 }
300 logger &= ~(LOGGER_LOGD | LOGGER_KERNEL | LOGGER_NULL | LOGGER_LOCAL |
301 LOGGER_STDERR);
302 if (logger) {
303 fprintf(stderr, "%s0x%x", prefix, logger);
304 prefix = orstr;
305 }
306 if (prefix == orstr) {
307 fprintf(stderr, "\n");
308 }
309 }
310 #endif
311
312 // This test makes little sense standalone, and requires the tests ahead
313 // and behind us, to make us whole. We could incorporate a prefix and
314 // suffix test to make this standalone, but opted to not complicate this.
TEST(liblog,android_set_log_transport)315 TEST(liblog, android_set_log_transport) {
316 #if (defined(__ANDROID__) || defined(USING_LOGGER_LOCAL))
317 #ifdef TEST_PREFIX
318 TEST_PREFIX
319 #endif
320
321 int logger = android_get_log_transport();
322 print_transport("android_get_log_transport = ", logger);
323 EXPECT_NE(LOGGER_NULL, logger);
324
325 int ret;
326 EXPECT_EQ(LOGGER_NULL, ret = android_set_log_transport(LOGGER_NULL));
327 print_transport("android_set_log_transport = ", ret);
328 EXPECT_EQ(LOGGER_NULL, ret = android_get_log_transport());
329 print_transport("android_get_log_transport = ", ret);
330
331 pid_t pid = getpid();
332
333 struct logger_list* logger_list;
334 ASSERT_TRUE(NULL !=
335 (logger_list = android_logger_list_open(
336 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
337 1000, pid)));
338
339 log_time ts(CLOCK_MONOTONIC);
340 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
341
342 usleep(1000000);
343
344 int count = 0;
345
346 for (;;) {
347 log_msg log_msg;
348 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
349 break;
350 }
351
352 EXPECT_EQ(log_msg.entry.pid, pid);
353
354 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
355 (log_msg.id() != LOG_ID_EVENTS)) {
356 continue;
357 }
358
359 android_log_event_long_t* eventData;
360 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
361
362 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
363 continue;
364 }
365
366 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
367 if (ts == tx) {
368 ++count;
369 }
370 }
371
372 android_logger_list_close(logger_list);
373
374 EXPECT_EQ(logger, ret = android_set_log_transport(logger));
375 print_transport("android_set_log_transport = ", ret);
376 EXPECT_EQ(logger, ret = android_get_log_transport());
377 print_transport("android_get_log_transport = ", ret);
378
379 // False negative if liblog.__android_log_btwrite__android_logger_list_read
380 // fails above, so we will likely succeed. But we will have so many
381 // failures elsewhere that it is probably not worthwhile for us to
382 // highlight yet another disappointment.
383 //
384 // We also expect failures in the following tests if the set does not
385 // react in an appropriate manner internally, yet passes, so we depend
386 // on this test being in the middle of a series of tests performed in
387 // the same process.
388 EXPECT_EQ(0, count);
389 #else
390 GTEST_LOG_(INFO) << "This test does nothing.\n";
391 #endif
392 }
393
394 #ifdef TEST_PREFIX
get4LE(const uint8_t * src)395 static inline uint32_t get4LE(const uint8_t* src) {
396 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
397 }
398
get4LE(const char * src)399 static inline uint32_t get4LE(const char* src) {
400 return get4LE(reinterpret_cast<const uint8_t*>(src));
401 }
402 #endif
403
bswrite_test(const char * message)404 static void bswrite_test(const char* message) {
405 #ifdef TEST_PREFIX
406 TEST_PREFIX
407 struct logger_list* logger_list;
408
409 pid_t pid = getpid();
410
411 ASSERT_TRUE(NULL !=
412 (logger_list = android_logger_list_open(
413 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
414 1000, pid)));
415
416 #ifdef __ANDROID__
417 log_time ts(android_log_clockid());
418 #else
419 log_time ts(CLOCK_REALTIME);
420 #endif
421
422 EXPECT_LT(0, __android_log_bswrite(0, message));
423 size_t num_lines = 1, size = 0, length = 0, total = 0;
424 const char* cp = message;
425 while (*cp) {
426 if (*cp == '\n') {
427 if (cp[1]) {
428 ++num_lines;
429 }
430 } else {
431 ++size;
432 }
433 ++cp;
434 ++total;
435 ++length;
436 if ((LOGGER_ENTRY_MAX_PAYLOAD - 4 - 1 - 4) <= length) {
437 break;
438 }
439 }
440 while (*cp) {
441 ++cp;
442 ++total;
443 }
444 usleep(1000000);
445
446 int count = 0;
447
448 for (;;) {
449 log_msg log_msg;
450 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
451 break;
452 }
453
454 EXPECT_EQ(log_msg.entry.pid, pid);
455
456 if ((log_msg.entry.sec < (ts.tv_sec - 1)) ||
457 ((ts.tv_sec + 1) < log_msg.entry.sec) ||
458 ((size_t)log_msg.entry.len !=
459 (sizeof(android_log_event_string_t) + length)) ||
460 (log_msg.id() != LOG_ID_EVENTS)) {
461 continue;
462 }
463
464 android_log_event_string_t* eventData;
465 eventData = reinterpret_cast<android_log_event_string_t*>(log_msg.msg());
466
467 if (!eventData || (eventData->type != EVENT_TYPE_STRING)) {
468 continue;
469 }
470
471 size_t len = get4LE(reinterpret_cast<char*>(&eventData->length));
472 if (len == total) {
473 ++count;
474
475 AndroidLogFormat* logformat = android_log_format_new();
476 EXPECT_TRUE(NULL != logformat);
477 AndroidLogEntry entry;
478 char msgBuf[1024];
479 if (length != total) {
480 fprintf(stderr, "Expect \"Binary log entry conversion failed\"\n");
481 }
482 int processBinaryLogBuffer = android_log_processBinaryLogBuffer(
483 &log_msg.entry_v1, &entry, NULL, msgBuf, sizeof(msgBuf));
484 EXPECT_EQ((length == total) ? 0 : -1, processBinaryLogBuffer);
485 if ((processBinaryLogBuffer == 0) || entry.message) {
486 size_t line_overhead = 20;
487 if (pid > 99999) ++line_overhead;
488 if (pid > 999999) ++line_overhead;
489 fflush(stderr);
490 if (processBinaryLogBuffer) {
491 EXPECT_GT((int)((line_overhead * num_lines) + size),
492 android_log_printLogLine(logformat, fileno(stderr), &entry));
493 } else {
494 EXPECT_EQ((int)((line_overhead * num_lines) + size),
495 android_log_printLogLine(logformat, fileno(stderr), &entry));
496 }
497 }
498 android_log_format_free(logformat);
499 }
500 }
501
502 EXPECT_EQ(SUPPORTS_END_TO_END, count);
503
504 android_logger_list_close(logger_list);
505 #else
506 message = NULL;
507 GTEST_LOG_(INFO) << "This test does nothing.\n";
508 #endif
509 }
510
TEST(liblog,__android_log_bswrite_and_print)511 TEST(liblog, __android_log_bswrite_and_print) {
512 bswrite_test("Hello World");
513 }
514
TEST(liblog,__android_log_bswrite_and_print__empty_string)515 TEST(liblog, __android_log_bswrite_and_print__empty_string) {
516 bswrite_test("");
517 }
518
TEST(liblog,__android_log_bswrite_and_print__newline_prefix)519 TEST(liblog, __android_log_bswrite_and_print__newline_prefix) {
520 bswrite_test("\nHello World\n");
521 }
522
TEST(liblog,__android_log_bswrite_and_print__newline_space_prefix)523 TEST(liblog, __android_log_bswrite_and_print__newline_space_prefix) {
524 bswrite_test("\n Hello World \n");
525 }
526
TEST(liblog,__android_log_bswrite_and_print__multiple_newline)527 TEST(liblog, __android_log_bswrite_and_print__multiple_newline) {
528 bswrite_test("one\ntwo\nthree\nfour\nfive\nsix\nseven\neight\nnine\nten");
529 }
530
buf_write_test(const char * message)531 static void buf_write_test(const char* message) {
532 #ifdef TEST_PREFIX
533 TEST_PREFIX
534 struct logger_list* logger_list;
535
536 pid_t pid = getpid();
537
538 ASSERT_TRUE(
539 NULL !=
540 (logger_list = android_logger_list_open(
541 LOG_ID_MAIN, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid)));
542
543 static const char tag[] = "TEST__android_log_buf_write";
544 #ifdef __ANDROID__
545 log_time ts(android_log_clockid());
546 #else
547 log_time ts(CLOCK_REALTIME);
548 #endif
549
550 EXPECT_LT(
551 0, __android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO, tag, message));
552 size_t num_lines = 1, size = 0, length = 0;
553 const char* cp = message;
554 while (*cp) {
555 if (*cp == '\n') {
556 if (cp[1]) {
557 ++num_lines;
558 }
559 } else {
560 ++size;
561 }
562 ++length;
563 if ((LOGGER_ENTRY_MAX_PAYLOAD - 2 - sizeof(tag)) <= length) {
564 break;
565 }
566 ++cp;
567 }
568 usleep(1000000);
569
570 int count = 0;
571
572 for (;;) {
573 log_msg log_msg;
574 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
575 break;
576 }
577
578 ASSERT_EQ(log_msg.entry.pid, pid);
579
580 if ((log_msg.entry.sec < (ts.tv_sec - 1)) ||
581 ((ts.tv_sec + 1) < log_msg.entry.sec) ||
582 ((size_t)log_msg.entry.len != (sizeof(tag) + length + 2)) ||
583 (log_msg.id() != LOG_ID_MAIN)) {
584 continue;
585 }
586
587 ++count;
588
589 AndroidLogFormat* logformat = android_log_format_new();
590 EXPECT_TRUE(NULL != logformat);
591 AndroidLogEntry entry;
592 int processLogBuffer =
593 android_log_processLogBuffer(&log_msg.entry_v1, &entry);
594 EXPECT_EQ(0, processLogBuffer);
595 if (processLogBuffer == 0) {
596 size_t line_overhead = 11;
597 if (pid > 99999) ++line_overhead;
598 if (pid > 999999) ++line_overhead;
599 fflush(stderr);
600 EXPECT_EQ((int)(((line_overhead + sizeof(tag)) * num_lines) + size),
601 android_log_printLogLine(logformat, fileno(stderr), &entry));
602 }
603 android_log_format_free(logformat);
604 }
605
606 EXPECT_EQ(SUPPORTS_END_TO_END, count);
607
608 android_logger_list_close(logger_list);
609 #else
610 message = NULL;
611 GTEST_LOG_(INFO) << "This test does nothing.\n";
612 #endif
613 }
614
TEST(liblog,__android_log_buf_write_and_print__empty)615 TEST(liblog, __android_log_buf_write_and_print__empty) {
616 buf_write_test("");
617 }
618
TEST(liblog,__android_log_buf_write_and_print__newline_prefix)619 TEST(liblog, __android_log_buf_write_and_print__newline_prefix) {
620 buf_write_test("\nHello World\n");
621 }
622
TEST(liblog,__android_log_buf_write_and_print__newline_space_prefix)623 TEST(liblog, __android_log_buf_write_and_print__newline_space_prefix) {
624 buf_write_test("\n Hello World \n");
625 }
626
627 #ifndef USING_LOGGER_LOCAL // requires blocking reader functionality
628 #ifdef TEST_PREFIX
629 static unsigned signaled;
630 static log_time signal_time;
631
632 /*
633 * Strictly, we are not allowed to log messages in a signal context, but we
634 * do make an effort to keep the failure surface minimized, and this in-effect
635 * should catch any regressions in that effort. The odds of a logged message
636 * in a signal handler causing a lockup problem should be _very_ small.
637 */
caught_blocking_signal(int)638 static void caught_blocking_signal(int /*signum*/) {
639 unsigned long long v = 0xDEADBEEFA55A0000ULL;
640
641 v += getpid() & 0xFFFF;
642
643 ++signaled;
644 if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) {
645 signal_time = log_time(CLOCK_MONOTONIC);
646 signal_time.tv_sec += 2;
647 }
648
649 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
650 }
651
652 // Fill in current process user and system time in 10ms increments
get_ticks(unsigned long long * uticks,unsigned long long * sticks)653 static void get_ticks(unsigned long long* uticks, unsigned long long* sticks) {
654 *uticks = *sticks = 0;
655
656 pid_t pid = getpid();
657
658 char buffer[512];
659 snprintf(buffer, sizeof(buffer), "/proc/%u/stat", pid);
660
661 FILE* fp = fopen(buffer, "r");
662 if (!fp) {
663 return;
664 }
665
666 char* cp = fgets(buffer, sizeof(buffer), fp);
667 fclose(fp);
668 if (!cp) {
669 return;
670 }
671
672 pid_t d;
673 char s[sizeof(buffer)];
674 char c;
675 long long ll;
676 unsigned long long ull;
677
678 if (15 != sscanf(buffer,
679 "%d %s %c %lld %lld %lld %lld %lld %llu %llu %llu %llu %llu "
680 "%llu %llu ",
681 &d, s, &c, &ll, &ll, &ll, &ll, &ll, &ull, &ull, &ull, &ull,
682 &ull, uticks, sticks)) {
683 *uticks = *sticks = 0;
684 }
685 }
686 #endif
687
TEST(liblog,android_logger_list_read__cpu_signal)688 TEST(liblog, android_logger_list_read__cpu_signal) {
689 #ifdef TEST_PREFIX
690 TEST_PREFIX
691 struct logger_list* logger_list;
692 unsigned long long v = 0xDEADBEEFA55A0000ULL;
693
694 pid_t pid = getpid();
695
696 v += pid & 0xFFFF;
697
698 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
699 LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 1000, pid)));
700
701 int count = 0;
702
703 int signals = 0;
704
705 unsigned long long uticks_start;
706 unsigned long long sticks_start;
707 get_ticks(&uticks_start, &sticks_start);
708
709 const unsigned alarm_time = 10;
710
711 memset(&signal_time, 0, sizeof(signal_time));
712
713 signal(SIGALRM, caught_blocking_signal);
714 alarm(alarm_time);
715
716 signaled = 0;
717
718 do {
719 log_msg log_msg;
720 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
721 break;
722 }
723
724 alarm(alarm_time);
725
726 ++count;
727
728 ASSERT_EQ(log_msg.entry.pid, pid);
729
730 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
731 (log_msg.id() != LOG_ID_EVENTS)) {
732 continue;
733 }
734
735 android_log_event_long_t* eventData;
736 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
737
738 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
739 continue;
740 }
741
742 char* cp = reinterpret_cast<char*>(&eventData->payload.data);
743 unsigned long long l = cp[0] & 0xFF;
744 l |= (unsigned long long)(cp[1] & 0xFF) << 8;
745 l |= (unsigned long long)(cp[2] & 0xFF) << 16;
746 l |= (unsigned long long)(cp[3] & 0xFF) << 24;
747 l |= (unsigned long long)(cp[4] & 0xFF) << 32;
748 l |= (unsigned long long)(cp[5] & 0xFF) << 40;
749 l |= (unsigned long long)(cp[6] & 0xFF) << 48;
750 l |= (unsigned long long)(cp[7] & 0xFF) << 56;
751
752 if (l == v) {
753 ++signals;
754 break;
755 }
756 } while (!signaled || (log_time(CLOCK_MONOTONIC) < signal_time));
757 alarm(0);
758 signal(SIGALRM, SIG_DFL);
759
760 EXPECT_LE(1, count);
761
762 EXPECT_EQ(1, signals);
763
764 android_logger_list_close(logger_list);
765
766 unsigned long long uticks_end;
767 unsigned long long sticks_end;
768 get_ticks(&uticks_end, &sticks_end);
769
770 // Less than 1% in either user or system time, or both
771 const unsigned long long one_percent_ticks = alarm_time;
772 unsigned long long user_ticks = uticks_end - uticks_start;
773 unsigned long long system_ticks = sticks_end - sticks_start;
774 EXPECT_GT(one_percent_ticks, user_ticks);
775 EXPECT_GT(one_percent_ticks, system_ticks);
776 EXPECT_GT(one_percent_ticks, user_ticks + system_ticks);
777 #else
778 GTEST_LOG_(INFO) << "This test does nothing.\n";
779 #endif
780 }
781
782 #ifdef TEST_PREFIX
783 /*
784 * Strictly, we are not allowed to log messages in a signal context, the
785 * correct way to handle this is to ensure the messages are constructed in
786 * a thread; the signal handler should only unblock the thread.
787 */
788 static sem_t thread_trigger;
789
caught_blocking_thread(int)790 static void caught_blocking_thread(int /*signum*/) {
791 sem_post(&thread_trigger);
792 }
793
running_thread(void *)794 static void* running_thread(void*) {
795 unsigned long long v = 0xDEADBEAFA55A0000ULL;
796
797 v += getpid() & 0xFFFF;
798
799 struct timespec timeout;
800 clock_gettime(CLOCK_REALTIME, &timeout);
801 timeout.tv_sec += 55;
802 sem_timedwait(&thread_trigger, &timeout);
803
804 ++signaled;
805 if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) {
806 signal_time = log_time(CLOCK_MONOTONIC);
807 signal_time.tv_sec += 2;
808 }
809
810 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
811
812 return NULL;
813 }
814
start_thread()815 static int start_thread() {
816 sem_init(&thread_trigger, 0, 0);
817
818 pthread_attr_t attr;
819 if (pthread_attr_init(&attr)) {
820 return -1;
821 }
822
823 struct sched_param param;
824
825 memset(¶m, 0, sizeof(param));
826 pthread_attr_setschedparam(&attr, ¶m);
827 pthread_attr_setschedpolicy(&attr, SCHED_BATCH);
828
829 if (pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED)) {
830 pthread_attr_destroy(&attr);
831 return -1;
832 }
833
834 pthread_t thread;
835 if (pthread_create(&thread, &attr, running_thread, NULL)) {
836 pthread_attr_destroy(&attr);
837 return -1;
838 }
839
840 pthread_attr_destroy(&attr);
841 return 0;
842 }
843 #endif
844
TEST(liblog,android_logger_list_read__cpu_thread)845 TEST(liblog, android_logger_list_read__cpu_thread) {
846 #ifdef TEST_PREFIX
847 TEST_PREFIX
848 struct logger_list* logger_list;
849 unsigned long long v = 0xDEADBEAFA55A0000ULL;
850
851 pid_t pid = getpid();
852
853 v += pid & 0xFFFF;
854
855 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
856 LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 1000, pid)));
857
858 int count = 0;
859
860 int signals = 0;
861
862 unsigned long long uticks_start;
863 unsigned long long sticks_start;
864 get_ticks(&uticks_start, &sticks_start);
865
866 const unsigned alarm_time = 10;
867
868 memset(&signal_time, 0, sizeof(signal_time));
869
870 signaled = 0;
871 EXPECT_EQ(0, start_thread());
872
873 signal(SIGALRM, caught_blocking_thread);
874 alarm(alarm_time);
875
876 do {
877 log_msg log_msg;
878 if (LOG_FAILURE_RETRY(android_logger_list_read(logger_list, &log_msg)) <= 0) {
879 break;
880 }
881
882 alarm(alarm_time);
883
884 ++count;
885
886 ASSERT_EQ(log_msg.entry.pid, pid);
887
888 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
889 (log_msg.id() != LOG_ID_EVENTS)) {
890 continue;
891 }
892
893 android_log_event_long_t* eventData;
894 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
895
896 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
897 continue;
898 }
899
900 char* cp = reinterpret_cast<char*>(&eventData->payload.data);
901 unsigned long long l = cp[0] & 0xFF;
902 l |= (unsigned long long)(cp[1] & 0xFF) << 8;
903 l |= (unsigned long long)(cp[2] & 0xFF) << 16;
904 l |= (unsigned long long)(cp[3] & 0xFF) << 24;
905 l |= (unsigned long long)(cp[4] & 0xFF) << 32;
906 l |= (unsigned long long)(cp[5] & 0xFF) << 40;
907 l |= (unsigned long long)(cp[6] & 0xFF) << 48;
908 l |= (unsigned long long)(cp[7] & 0xFF) << 56;
909
910 if (l == v) {
911 ++signals;
912 break;
913 }
914 } while (!signaled || (log_time(CLOCK_MONOTONIC) < signal_time));
915 alarm(0);
916 signal(SIGALRM, SIG_DFL);
917
918 EXPECT_LE(1, count);
919
920 EXPECT_EQ(1, signals);
921
922 android_logger_list_close(logger_list);
923
924 unsigned long long uticks_end;
925 unsigned long long sticks_end;
926 get_ticks(&uticks_end, &sticks_end);
927
928 // Less than 1% in either user or system time, or both
929 const unsigned long long one_percent_ticks = alarm_time;
930 unsigned long long user_ticks = uticks_end - uticks_start;
931 unsigned long long system_ticks = sticks_end - sticks_start;
932 EXPECT_GT(one_percent_ticks, user_ticks);
933 EXPECT_GT(one_percent_ticks, system_ticks);
934 EXPECT_GT(one_percent_ticks, user_ticks + system_ticks);
935 #else
936 GTEST_LOG_(INFO) << "This test does nothing.\n";
937 #endif
938 }
939 #endif // !USING_LOGGER_LOCAL
940
941 #ifdef TEST_PREFIX
942 static const char max_payload_tag[] = "TEST_max_payload_and_longish_tag_XXXX";
943 #define SIZEOF_MAX_PAYLOAD_BUF \
944 (LOGGER_ENTRY_MAX_PAYLOAD - sizeof(max_payload_tag) - 1)
945 #endif
946 static const char max_payload_buf[] =
947 "LEONATO\n\
948 I learn in this letter that Don Peter of Arragon\n\
949 comes this night to Messina\n\
950 MESSENGER\n\
951 He is very near by this: he was not three leagues off\n\
952 when I left him\n\
953 LEONATO\n\
954 How many gentlemen have you lost in this action?\n\
955 MESSENGER\n\
956 But few of any sort, and none of name\n\
957 LEONATO\n\
958 A victory is twice itself when the achiever brings\n\
959 home full numbers. I find here that Don Peter hath\n\
960 bestowed much honour on a young Florentine called Claudio\n\
961 MESSENGER\n\
962 Much deserved on his part and equally remembered by\n\
963 Don Pedro: he hath borne himself beyond the\n\
964 promise of his age, doing, in the figure of a lamb,\n\
965 the feats of a lion: he hath indeed better\n\
966 bettered expectation than you must expect of me to\n\
967 tell you how\n\
968 LEONATO\n\
969 He hath an uncle here in Messina will be very much\n\
970 glad of it.\n\
971 MESSENGER\n\
972 I have already delivered him letters, and there\n\
973 appears much joy in him; even so much that joy could\n\
974 not show itself modest enough without a badge of\n\
975 bitterness.\n\
976 LEONATO\n\
977 Did he break out into tears?\n\
978 MESSENGER\n\
979 In great measure.\n\
980 LEONATO\n\
981 A kind overflow of kindness: there are no faces\n\
982 truer than those that are so washed. How much\n\
983 better is it to weep at joy than to joy at weeping!\n\
984 BEATRICE\n\
985 I pray you, is Signior Mountanto returned from the\n\
986 wars or no?\n\
987 MESSENGER\n\
988 I know none of that name, lady: there was none such\n\
989 in the army of any sort.\n\
990 LEONATO\n\
991 What is he that you ask for, niece?\n\
992 HERO\n\
993 My cousin means Signior Benedick of Padua.\n\
994 MESSENGER\n\
995 O, he's returned; and as pleasant as ever he was.\n\
996 BEATRICE\n\
997 He set up his bills here in Messina and challenged\n\
998 Cupid at the flight; and my uncle's fool, reading\n\
999 the challenge, subscribed for Cupid, and challenged\n\
1000 him at the bird-bolt. I pray you, how many hath he\n\
1001 killed and eaten in these wars? But how many hath\n\
1002 he killed? for indeed I promised to eat all of his killing.\n\
1003 LEONATO\n\
1004 Faith, niece, you tax Signior Benedick too much;\n\
1005 but he'll be meet with you, I doubt it not.\n\
1006 MESSENGER\n\
1007 He hath done good service, lady, in these wars.\n\
1008 BEATRICE\n\
1009 You had musty victual, and he hath holp to eat it:\n\
1010 he is a very valiant trencherman; he hath an\n\
1011 excellent stomach.\n\
1012 MESSENGER\n\
1013 And a good soldier too, lady.\n\
1014 BEATRICE\n\
1015 And a good soldier to a lady: but what is he to a lord?\n\
1016 MESSENGER\n\
1017 A lord to a lord, a man to a man; stuffed with all\n\
1018 honourable virtues.\n\
1019 BEATRICE\n\
1020 It is so, indeed; he is no less than a stuffed man:\n\
1021 but for the stuffing,--well, we are all mortal.\n\
1022 LEONATO\n\
1023 You must not, sir, mistake my niece. There is a\n\
1024 kind of merry war betwixt Signior Benedick and her:\n\
1025 they never meet but there's a skirmish of wit\n\
1026 between them.\n\
1027 BEATRICE\n\
1028 Alas! he gets nothing by that. In our last\n\
1029 conflict four of his five wits went halting off, and\n\
1030 now is the whole man governed with one: so that if\n\
1031 he have wit enough to keep himself warm, let him\n\
1032 bear it for a difference between himself and his\n\
1033 horse; for it is all the wealth that he hath left,\n\
1034 to be known a reasonable creature. Who is his\n\
1035 companion now? He hath every month a new sworn brother.\n\
1036 MESSENGER\n\
1037 Is't possible?\n\
1038 BEATRICE\n\
1039 Very easily possible: he wears his faith but as\n\
1040 the fashion of his hat; it ever changes with the\n\
1041 next block.\n\
1042 MESSENGER\n\
1043 I see, lady, the gentleman is not in your books.\n\
1044 BEATRICE\n\
1045 No; an he were, I would burn my study. But, I pray\n\
1046 you, who is his companion? Is there no young\n\
1047 squarer now that will make a voyage with him to the devil?\n\
1048 MESSENGER\n\
1049 He is most in the company of the right noble Claudio.\n\
1050 BEATRICE\n\
1051 O Lord, he will hang upon him like a disease: he\n\
1052 is sooner caught than the pestilence, and the taker\n\
1053 runs presently mad. God help the noble Claudio! if\n\
1054 he have caught the Benedick, it will cost him a\n\
1055 thousand pound ere a' be cured.\n\
1056 MESSENGER\n\
1057 I will hold friends with you, lady.\n\
1058 BEATRICE\n\
1059 Do, good friend.\n\
1060 LEONATO\n\
1061 You will never run mad, niece.\n\
1062 BEATRICE\n\
1063 No, not till a hot January.\n\
1064 MESSENGER\n\
1065 Don Pedro is approached.\n\
1066 Enter DON PEDRO, DON JOHN, CLAUDIO, BENEDICK, and BALTHASAR\n\
1067 \n\
1068 DON PEDRO\n\
1069 Good Signior Leonato, you are come to meet your\n\
1070 trouble: the fashion of the world is to avoid\n\
1071 cost, and you encounter it\n\
1072 LEONATO\n\
1073 Never came trouble to my house in the likeness of your grace,\n\
1074 for trouble being gone, comfort should remain, but\n\
1075 when you depart from me, sorrow abides and happiness\n\
1076 takes his leave.";
1077
TEST(liblog,max_payload)1078 TEST(liblog, max_payload) {
1079 #ifdef TEST_PREFIX
1080 TEST_PREFIX
1081 pid_t pid = getpid();
1082 char tag[sizeof(max_payload_tag)];
1083 memcpy(tag, max_payload_tag, sizeof(tag));
1084 snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
1085
1086 LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
1087 tag, max_payload_buf));
1088 sleep(2);
1089
1090 struct logger_list* logger_list;
1091
1092 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
1093 LOG_ID_SYSTEM, ANDROID_LOG_RDONLY, 100, 0)));
1094
1095 bool matches = false;
1096 ssize_t max_len = 0;
1097
1098 for (;;) {
1099 log_msg log_msg;
1100 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
1101 break;
1102 }
1103
1104 if ((log_msg.entry.pid != pid) || (log_msg.id() != LOG_ID_SYSTEM)) {
1105 continue;
1106 }
1107
1108 char* data = log_msg.msg();
1109
1110 if (!data || strcmp(++data, tag)) {
1111 continue;
1112 }
1113
1114 data += strlen(data) + 1;
1115
1116 const char* left = data;
1117 const char* right = max_payload_buf;
1118 while (*left && *right && (*left == *right)) {
1119 ++left;
1120 ++right;
1121 }
1122
1123 if (max_len <= (left - data)) {
1124 max_len = left - data + 1;
1125 }
1126
1127 if (max_len > 512) {
1128 matches = true;
1129 break;
1130 }
1131 }
1132
1133 android_logger_list_close(logger_list);
1134
1135 #if SUPPORTS_END_TO_END
1136 EXPECT_EQ(true, matches);
1137
1138 EXPECT_LE(SIZEOF_MAX_PAYLOAD_BUF, static_cast<size_t>(max_len));
1139 #else
1140 EXPECT_EQ(false, matches);
1141 #endif
1142 #else
1143 GTEST_LOG_(INFO) << "This test does nothing.\n";
1144 #endif
1145 }
1146
TEST(liblog,__android_log_buf_print__maxtag)1147 TEST(liblog, __android_log_buf_print__maxtag) {
1148 #ifdef TEST_PREFIX
1149 TEST_PREFIX
1150 struct logger_list* logger_list;
1151
1152 pid_t pid = getpid();
1153
1154 ASSERT_TRUE(
1155 NULL !=
1156 (logger_list = android_logger_list_open(
1157 LOG_ID_MAIN, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid)));
1158
1159 #ifdef __ANDROID__
1160 log_time ts(android_log_clockid());
1161 #else
1162 log_time ts(CLOCK_REALTIME);
1163 #endif
1164
1165 EXPECT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
1166 max_payload_buf, max_payload_buf));
1167 usleep(1000000);
1168
1169 int count = 0;
1170
1171 for (;;) {
1172 log_msg log_msg;
1173 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
1174 break;
1175 }
1176
1177 ASSERT_EQ(log_msg.entry.pid, pid);
1178
1179 if ((log_msg.entry.sec < (ts.tv_sec - 1)) ||
1180 ((ts.tv_sec + 1) < log_msg.entry.sec) ||
1181 ((size_t)log_msg.entry.len < LOGGER_ENTRY_MAX_PAYLOAD) ||
1182 (log_msg.id() != LOG_ID_MAIN)) {
1183 continue;
1184 }
1185
1186 ++count;
1187
1188 AndroidLogFormat* logformat = android_log_format_new();
1189 EXPECT_TRUE(NULL != logformat);
1190 AndroidLogEntry entry;
1191 int processLogBuffer =
1192 android_log_processLogBuffer(&log_msg.entry_v1, &entry);
1193 EXPECT_EQ(0, processLogBuffer);
1194 if (processLogBuffer == 0) {
1195 fflush(stderr);
1196 int printLogLine =
1197 android_log_printLogLine(logformat, fileno(stderr), &entry);
1198 // Legacy tag truncation
1199 EXPECT_LE(128, printLogLine);
1200 // Measured maximum if we try to print part of the tag as message
1201 EXPECT_GT(LOGGER_ENTRY_MAX_PAYLOAD * 13 / 8, printLogLine);
1202 }
1203 android_log_format_free(logformat);
1204 }
1205
1206 EXPECT_EQ(SUPPORTS_END_TO_END, count);
1207
1208 android_logger_list_close(logger_list);
1209 #else
1210 GTEST_LOG_(INFO) << "This test does nothing.\n";
1211 #endif
1212 }
1213
TEST(liblog,too_big_payload)1214 TEST(liblog, too_big_payload) {
1215 #ifdef TEST_PREFIX
1216 TEST_PREFIX
1217 pid_t pid = getpid();
1218 static const char big_payload_tag[] = "TEST_big_payload_XXXX";
1219 char tag[sizeof(big_payload_tag)];
1220 memcpy(tag, big_payload_tag, sizeof(tag));
1221 snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
1222
1223 std::string longString(3266519, 'x');
1224
1225 ssize_t ret = LOG_FAILURE_RETRY(__android_log_buf_write(
1226 LOG_ID_SYSTEM, ANDROID_LOG_INFO, tag, longString.c_str()));
1227
1228 struct logger_list* logger_list;
1229
1230 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
1231 LOG_ID_SYSTEM,
1232 ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 100, 0)));
1233
1234 ssize_t max_len = 0;
1235
1236 for (;;) {
1237 log_msg log_msg;
1238 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
1239 break;
1240 }
1241
1242 if ((log_msg.entry.pid != pid) || (log_msg.id() != LOG_ID_SYSTEM)) {
1243 continue;
1244 }
1245
1246 char* data = log_msg.msg();
1247
1248 if (!data || strcmp(++data, tag)) {
1249 continue;
1250 }
1251
1252 data += strlen(data) + 1;
1253
1254 const char* left = data;
1255 const char* right = longString.c_str();
1256 while (*left && *right && (*left == *right)) {
1257 ++left;
1258 ++right;
1259 }
1260
1261 if (max_len <= (left - data)) {
1262 max_len = left - data + 1;
1263 }
1264 }
1265
1266 android_logger_list_close(logger_list);
1267
1268 #if !SUPPORTS_END_TO_END
1269 max_len =
1270 max_len ? max_len : LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag);
1271 #endif
1272 EXPECT_LE(LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag),
1273 static_cast<size_t>(max_len));
1274
1275 // SLOP: Allow the underlying interface to optionally place a
1276 // terminating nul at the LOGGER_ENTRY_MAX_PAYLOAD's last byte
1277 // or not.
1278 if (ret == (max_len + static_cast<ssize_t>(sizeof(big_payload_tag)) - 1)) {
1279 --max_len;
1280 }
1281 EXPECT_EQ(ret, max_len + static_cast<ssize_t>(sizeof(big_payload_tag)));
1282 #else
1283 GTEST_LOG_(INFO) << "This test does nothing.\n";
1284 #endif
1285 }
1286
TEST(liblog,dual_reader)1287 TEST(liblog, dual_reader) {
1288 #ifdef TEST_PREFIX
1289 TEST_PREFIX
1290
1291 static const int num = 25;
1292
1293 for (int i = 25; i > 0; --i) {
1294 static const char fmt[] = "dual_reader %02d";
1295 char buffer[sizeof(fmt) + 8];
1296 snprintf(buffer, sizeof(buffer), fmt, i);
1297 LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO,
1298 "liblog", buffer));
1299 }
1300 usleep(1000000);
1301
1302 struct logger_list* logger_list1;
1303 ASSERT_TRUE(NULL != (logger_list1 = android_logger_list_open(
1304 LOG_ID_MAIN,
1305 ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, num, 0)));
1306
1307 struct logger_list* logger_list2;
1308
1309 if (NULL == (logger_list2 = android_logger_list_open(
1310 LOG_ID_MAIN, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
1311 num - 10, 0))) {
1312 android_logger_list_close(logger_list1);
1313 ASSERT_TRUE(NULL != logger_list2);
1314 }
1315
1316 int count1 = 0;
1317 bool done1 = false;
1318 int count2 = 0;
1319 bool done2 = false;
1320
1321 do {
1322 log_msg log_msg;
1323
1324 if (!done1) {
1325 if (android_logger_list_read(logger_list1, &log_msg) <= 0) {
1326 done1 = true;
1327 } else {
1328 ++count1;
1329 }
1330 }
1331
1332 if (!done2) {
1333 if (android_logger_list_read(logger_list2, &log_msg) <= 0) {
1334 done2 = true;
1335 } else {
1336 ++count2;
1337 }
1338 }
1339 } while ((!done1) || (!done2));
1340
1341 android_logger_list_close(logger_list1);
1342 android_logger_list_close(logger_list2);
1343
1344 EXPECT_EQ(num * SUPPORTS_END_TO_END, count1);
1345 EXPECT_EQ((num - 10) * SUPPORTS_END_TO_END, count2);
1346 #else
1347 GTEST_LOG_(INFO) << "This test does nothing.\n";
1348 #endif
1349 }
1350
1351 #ifdef USING_LOGGER_DEFAULT // Do not retest logprint
checkPriForTag(AndroidLogFormat * p_format,const char * tag,android_LogPriority pri)1352 static bool checkPriForTag(AndroidLogFormat* p_format, const char* tag,
1353 android_LogPriority pri) {
1354 return android_log_shouldPrintLine(p_format, tag, pri) &&
1355 !android_log_shouldPrintLine(p_format, tag,
1356 (android_LogPriority)(pri - 1));
1357 }
1358
TEST(liblog,filterRule)1359 TEST(liblog, filterRule) {
1360 static const char tag[] = "random";
1361
1362 AndroidLogFormat* p_format = android_log_format_new();
1363
1364 android_log_addFilterRule(p_format, "*:i");
1365
1366 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_INFO));
1367 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1368 0);
1369 android_log_addFilterRule(p_format, "*");
1370 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1371 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1372 android_log_addFilterRule(p_format, "*:v");
1373 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_VERBOSE));
1374 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1375 android_log_addFilterRule(p_format, "*:i");
1376 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_INFO));
1377 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1378 0);
1379
1380 android_log_addFilterRule(p_format, tag);
1381 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_VERBOSE));
1382 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1383 android_log_addFilterRule(p_format, "random:v");
1384 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_VERBOSE));
1385 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1386 android_log_addFilterRule(p_format, "random:d");
1387 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1388 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1389 android_log_addFilterRule(p_format, "random:w");
1390 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1391 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1392 0);
1393
1394 android_log_addFilterRule(p_format, "crap:*");
1395 EXPECT_TRUE(checkPriForTag(p_format, "crap", ANDROID_LOG_VERBOSE));
1396 EXPECT_TRUE(
1397 android_log_shouldPrintLine(p_format, "crap", ANDROID_LOG_VERBOSE) > 0);
1398
1399 // invalid expression
1400 EXPECT_TRUE(android_log_addFilterRule(p_format, "random:z") < 0);
1401 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1402 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1403 0);
1404
1405 // Issue #550946
1406 EXPECT_TRUE(android_log_addFilterString(p_format, " ") == 0);
1407 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1408
1409 // note trailing space
1410 EXPECT_TRUE(android_log_addFilterString(p_format, "*:s random:d ") == 0);
1411 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1412
1413 EXPECT_TRUE(android_log_addFilterString(p_format, "*:s random:z") < 0);
1414
1415 #if 0 // bitrot, seek update
1416 char defaultBuffer[512];
1417
1418 android_log_formatLogLine(p_format,
1419 defaultBuffer, sizeof(defaultBuffer), 0, ANDROID_LOG_ERROR, 123,
1420 123, 123, tag, "nofile", strlen("Hello"), "Hello", NULL);
1421
1422 fprintf(stderr, "%s\n", defaultBuffer);
1423 #endif
1424
1425 android_log_format_free(p_format);
1426 }
1427 #endif // USING_LOGGER_DEFAULT
1428
1429 #ifdef USING_LOGGER_DEFAULT // Do not retest property handling
TEST(liblog,is_loggable)1430 TEST(liblog, is_loggable) {
1431 #ifdef __ANDROID__
1432 static const char tag[] = "is_loggable";
1433 static const char log_namespace[] = "persist.log.tag.";
1434 static const size_t base_offset = 8; /* skip "persist." */
1435 // sizeof("string") = strlen("string") + 1
1436 char key[sizeof(log_namespace) + sizeof(tag) - 1];
1437 char hold[4][PROP_VALUE_MAX];
1438 static const struct {
1439 int level;
1440 char type;
1441 } levels[] = {
1442 { ANDROID_LOG_VERBOSE, 'v' },
1443 { ANDROID_LOG_DEBUG, 'd' },
1444 { ANDROID_LOG_INFO, 'i' },
1445 { ANDROID_LOG_WARN, 'w' },
1446 { ANDROID_LOG_ERROR, 'e' },
1447 { ANDROID_LOG_FATAL, 'a' },
1448 { -1, 's' },
1449 { -2, 'g' }, // Illegal value, resort to default
1450 };
1451
1452 // Set up initial test condition
1453 memset(hold, 0, sizeof(hold));
1454 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1455 property_get(key, hold[0], "");
1456 property_set(key, "");
1457 property_get(key + base_offset, hold[1], "");
1458 property_set(key + base_offset, "");
1459 strcpy(key, log_namespace);
1460 key[sizeof(log_namespace) - 2] = '\0';
1461 property_get(key, hold[2], "");
1462 property_set(key, "");
1463 property_get(key, hold[3], "");
1464 property_set(key + base_offset, "");
1465
1466 // All combinations of level and defaults
1467 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1468 if (levels[i].level == -2) {
1469 continue;
1470 }
1471 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1472 if (levels[j].level == -2) {
1473 continue;
1474 }
1475 fprintf(stderr, "i=%zu j=%zu\r", i, j);
1476 bool android_log_is_loggable = __android_log_is_loggable_len(
1477 levels[i].level, tag, strlen(tag), levels[j].level);
1478 if ((levels[i].level < levels[j].level) || (levels[j].level == -1)) {
1479 if (android_log_is_loggable) {
1480 fprintf(stderr, "\n");
1481 }
1482 EXPECT_FALSE(android_log_is_loggable);
1483 for (size_t k = 10; k; --k) {
1484 EXPECT_FALSE(__android_log_is_loggable_len(
1485 levels[i].level, tag, strlen(tag), levels[j].level));
1486 }
1487 } else {
1488 if (!android_log_is_loggable) {
1489 fprintf(stderr, "\n");
1490 }
1491 EXPECT_TRUE(android_log_is_loggable);
1492 for (size_t k = 10; k; --k) {
1493 EXPECT_TRUE(__android_log_is_loggable_len(
1494 levels[i].level, tag, strlen(tag), levels[j].level));
1495 }
1496 }
1497 }
1498 }
1499
1500 // All combinations of level and tag and global properties
1501 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1502 if (levels[i].level == -2) {
1503 continue;
1504 }
1505 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1506 char buf[2];
1507 buf[0] = levels[j].type;
1508 buf[1] = '\0';
1509
1510 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1511 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1512 buf);
1513 usleep(20000);
1514 property_set(key, buf);
1515 bool android_log_is_loggable = __android_log_is_loggable_len(
1516 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1517 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1518 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1519 if (android_log_is_loggable) {
1520 fprintf(stderr, "\n");
1521 }
1522 EXPECT_FALSE(android_log_is_loggable);
1523 for (size_t k = 10; k; --k) {
1524 EXPECT_FALSE(__android_log_is_loggable_len(
1525 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1526 }
1527 } else {
1528 if (!android_log_is_loggable) {
1529 fprintf(stderr, "\n");
1530 }
1531 EXPECT_TRUE(android_log_is_loggable);
1532 for (size_t k = 10; k; --k) {
1533 EXPECT_TRUE(__android_log_is_loggable_len(
1534 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1535 }
1536 }
1537 usleep(20000);
1538 property_set(key, "");
1539
1540 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1541 key + base_offset, buf);
1542 property_set(key + base_offset, buf);
1543 android_log_is_loggable = __android_log_is_loggable_len(
1544 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1545 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1546 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1547 if (android_log_is_loggable) {
1548 fprintf(stderr, "\n");
1549 }
1550 EXPECT_FALSE(android_log_is_loggable);
1551 for (size_t k = 10; k; --k) {
1552 EXPECT_FALSE(__android_log_is_loggable_len(
1553 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1554 }
1555 } else {
1556 if (!android_log_is_loggable) {
1557 fprintf(stderr, "\n");
1558 }
1559 EXPECT_TRUE(android_log_is_loggable);
1560 for (size_t k = 10; k; --k) {
1561 EXPECT_TRUE(__android_log_is_loggable_len(
1562 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1563 }
1564 }
1565 usleep(20000);
1566 property_set(key + base_offset, "");
1567
1568 strcpy(key, log_namespace);
1569 key[sizeof(log_namespace) - 2] = '\0';
1570 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1571 buf);
1572 property_set(key, buf);
1573 android_log_is_loggable = __android_log_is_loggable_len(
1574 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1575 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1576 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1577 if (android_log_is_loggable) {
1578 fprintf(stderr, "\n");
1579 }
1580 EXPECT_FALSE(android_log_is_loggable);
1581 for (size_t k = 10; k; --k) {
1582 EXPECT_FALSE(__android_log_is_loggable_len(
1583 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1584 }
1585 } else {
1586 if (!android_log_is_loggable) {
1587 fprintf(stderr, "\n");
1588 }
1589 EXPECT_TRUE(android_log_is_loggable);
1590 for (size_t k = 10; k; --k) {
1591 EXPECT_TRUE(__android_log_is_loggable_len(
1592 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1593 }
1594 }
1595 usleep(20000);
1596 property_set(key, "");
1597
1598 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1599 key + base_offset, buf);
1600 property_set(key + base_offset, buf);
1601 android_log_is_loggable = __android_log_is_loggable_len(
1602 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1603 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1604 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1605 if (android_log_is_loggable) {
1606 fprintf(stderr, "\n");
1607 }
1608 EXPECT_FALSE(android_log_is_loggable);
1609 for (size_t k = 10; k; --k) {
1610 EXPECT_FALSE(__android_log_is_loggable_len(
1611 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1612 }
1613 } else {
1614 if (!android_log_is_loggable) {
1615 fprintf(stderr, "\n");
1616 }
1617 EXPECT_TRUE(android_log_is_loggable);
1618 for (size_t k = 10; k; --k) {
1619 EXPECT_TRUE(__android_log_is_loggable_len(
1620 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1621 }
1622 }
1623 usleep(20000);
1624 property_set(key + base_offset, "");
1625 }
1626 }
1627
1628 // All combinations of level and tag properties, but with global set to INFO
1629 strcpy(key, log_namespace);
1630 key[sizeof(log_namespace) - 2] = '\0';
1631 usleep(20000);
1632 property_set(key, "I");
1633 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1634 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1635 if (levels[i].level == -2) {
1636 continue;
1637 }
1638 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1639 char buf[2];
1640 buf[0] = levels[j].type;
1641 buf[1] = '\0';
1642
1643 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1644 buf);
1645 usleep(20000);
1646 property_set(key, buf);
1647 bool android_log_is_loggable = __android_log_is_loggable_len(
1648 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1649 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1650 ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
1651 && (levels[j].level == -2))) {
1652 if (android_log_is_loggable) {
1653 fprintf(stderr, "\n");
1654 }
1655 EXPECT_FALSE(android_log_is_loggable);
1656 for (size_t k = 10; k; --k) {
1657 EXPECT_FALSE(__android_log_is_loggable_len(
1658 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1659 }
1660 } else {
1661 if (!android_log_is_loggable) {
1662 fprintf(stderr, "\n");
1663 }
1664 EXPECT_TRUE(android_log_is_loggable);
1665 for (size_t k = 10; k; --k) {
1666 EXPECT_TRUE(__android_log_is_loggable_len(
1667 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1668 }
1669 }
1670 usleep(20000);
1671 property_set(key, "");
1672
1673 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1674 key + base_offset, buf);
1675 property_set(key + base_offset, buf);
1676 android_log_is_loggable = __android_log_is_loggable_len(
1677 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1678 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1679 ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
1680 && (levels[j].level == -2))) {
1681 if (android_log_is_loggable) {
1682 fprintf(stderr, "\n");
1683 }
1684 EXPECT_FALSE(android_log_is_loggable);
1685 for (size_t k = 10; k; --k) {
1686 EXPECT_FALSE(__android_log_is_loggable_len(
1687 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1688 }
1689 } else {
1690 if (!android_log_is_loggable) {
1691 fprintf(stderr, "\n");
1692 }
1693 EXPECT_TRUE(android_log_is_loggable);
1694 for (size_t k = 10; k; --k) {
1695 EXPECT_TRUE(__android_log_is_loggable_len(
1696 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1697 }
1698 }
1699 usleep(20000);
1700 property_set(key + base_offset, "");
1701 }
1702 }
1703
1704 // reset parms
1705 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1706 usleep(20000);
1707 property_set(key, hold[0]);
1708 property_set(key + base_offset, hold[1]);
1709 strcpy(key, log_namespace);
1710 key[sizeof(log_namespace) - 2] = '\0';
1711 property_set(key, hold[2]);
1712 property_set(key + base_offset, hold[3]);
1713 #else
1714 GTEST_LOG_(INFO) << "This test does nothing.\n";
1715 #endif
1716 }
1717 #endif // USING_LOGGER_DEFAULT
1718
1719 // Following tests the specific issues surrounding error handling wrt logd.
1720 // Kills logd and toss all collected data, equivalent to logcat -b all -c,
1721 // except we also return errors to the logging callers.
1722 #ifdef USING_LOGGER_DEFAULT
1723 #ifdef TEST_PREFIX
1724 // helper to liblog.enoent to count end-to-end matching logging messages.
count_matching_ts(log_time ts)1725 static int count_matching_ts(log_time ts) {
1726 usleep(1000000);
1727
1728 pid_t pid = getpid();
1729
1730 struct logger_list* logger_list = android_logger_list_open(
1731 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid);
1732
1733 int count = 0;
1734 if (logger_list == NULL) return count;
1735
1736 for (;;) {
1737 log_msg log_msg;
1738 if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
1739
1740 if (log_msg.entry.len != sizeof(android_log_event_long_t)) continue;
1741 if (log_msg.id() != LOG_ID_EVENTS) continue;
1742
1743 android_log_event_long_t* eventData;
1744 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
1745 if (!eventData) continue;
1746 if (eventData->payload.type != EVENT_TYPE_LONG) continue;
1747
1748 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
1749 if (ts != tx) continue;
1750
1751 // found event message with matching timestamp signature in payload
1752 ++count;
1753 }
1754 android_logger_list_close(logger_list);
1755
1756 return count;
1757 }
1758
1759 // meant to be handed to ASSERT_TRUE / EXPECT_TRUE only to expand the message
IsOk(bool ok,std::string & message)1760 static testing::AssertionResult IsOk(bool ok, std::string& message) {
1761 return ok ? testing::AssertionSuccess()
1762 : (testing::AssertionFailure() << message);
1763 }
1764 #endif // TEST_PREFIX
1765
TEST(liblog,enoent)1766 TEST(liblog, enoent) {
1767 #ifdef TEST_PREFIX
1768 TEST_PREFIX
1769 log_time ts(CLOCK_MONOTONIC);
1770 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
1771 EXPECT_EQ(SUPPORTS_END_TO_END, count_matching_ts(ts));
1772
1773 // This call will fail if we are setuid(AID_SYSTEM), beware of any
1774 // test prior to this one playing with setuid and causing interference.
1775 // We need to run before these tests so that they do not interfere with
1776 // this test.
1777 //
1778 // Stopping the logger can affect some other test's expectations as they
1779 // count on the log buffers filled with existing content, and this
1780 // effectively does a logcat -c emptying it. So we want this test to be
1781 // as near as possible to the bottom of the file. For example
1782 // liblog.android_logger_get_ is one of those tests that has no recourse
1783 // and that would be adversely affected by emptying the log if it was run
1784 // right after this test.
1785 if (getuid() != AID_ROOT) {
1786 fprintf(
1787 stderr,
1788 "WARNING: test conditions request being run as root and not AID=%d\n",
1789 getuid());
1790 if (!__android_log_is_debuggable()) {
1791 fprintf(
1792 stderr,
1793 "WARNING: can not run test on a \"user\" build, bypassing test\n");
1794 return;
1795 }
1796 }
1797
1798 system((getuid() == AID_ROOT) ? "stop logd" : "su 0 stop logd");
1799 usleep(1000000);
1800
1801 // A clean stop like we are testing returns -ENOENT, but in the _real_
1802 // world we could get -ENOTCONN or -ECONNREFUSED depending on timing.
1803 // Alas we can not test these other return values; accept that they
1804 // are treated equally within the open-retry logic in liblog.
1805 ts = log_time(CLOCK_MONOTONIC);
1806 int ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
1807 std::string content = android::base::StringPrintf(
1808 "__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
1809 ret, (ret <= 0) ? strerror(-ret) : "(content sent)");
1810 EXPECT_TRUE(
1811 IsOk((ret == -ENOENT) || (ret == -ENOTCONN) || (ret == -ECONNREFUSED),
1812 content));
1813 ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
1814 content = android::base::StringPrintf(
1815 "__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
1816 ret, (ret <= 0) ? strerror(-ret) : "(content sent)");
1817 EXPECT_TRUE(
1818 IsOk((ret == -ENOENT) || (ret == -ENOTCONN) || (ret == -ECONNREFUSED),
1819 content));
1820 EXPECT_EQ(0, count_matching_ts(ts));
1821
1822 system((getuid() == AID_ROOT) ? "start logd" : "su 0 start logd");
1823 usleep(1000000);
1824
1825 EXPECT_EQ(0, count_matching_ts(ts));
1826
1827 ts = log_time(CLOCK_MONOTONIC);
1828 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
1829 EXPECT_EQ(SUPPORTS_END_TO_END, count_matching_ts(ts));
1830
1831 #else
1832 GTEST_LOG_(INFO) << "This test does nothing.\n";
1833 #endif
1834 }
1835 #endif // USING_LOCAL_LOGD
1836
1837 // Below this point we run risks of setuid(AID_SYSTEM) which may affect others.
1838
1839 // Do not retest properties, and cannot log into LOG_ID_SECURITY
1840 #ifdef USING_LOGGER_DEFAULT
TEST(liblog,__security)1841 TEST(liblog, __security) {
1842 #ifdef __ANDROID__
1843 static const char persist_key[] = "persist.logd.security";
1844 static const char readonly_key[] = "ro.device_owner";
1845 // A silly default value that can never be in readonly_key so
1846 // that it can be determined the property is not set.
1847 static const char nothing_val[] = "_NOTHING_TO_SEE_HERE_";
1848 char persist[PROP_VALUE_MAX];
1849 char persist_hold[PROP_VALUE_MAX];
1850 char readonly[PROP_VALUE_MAX];
1851
1852 // First part of this test requires the test itself to have the appropriate
1853 // permissions. If we do not have them, we can not override them, so we
1854 // bail rather than give a failing grade.
1855 property_get(persist_key, persist, "");
1856 fprintf(stderr, "INFO: getprop %s -> %s\n", persist_key, persist);
1857 strncpy(persist_hold, persist, PROP_VALUE_MAX);
1858 property_get(readonly_key, readonly, nothing_val);
1859 fprintf(stderr, "INFO: getprop %s -> %s\n", readonly_key, readonly);
1860
1861 if (!strcmp(readonly, nothing_val)) {
1862 // Lets check if we can set the value (we should not be allowed to do so)
1863 EXPECT_FALSE(__android_log_security());
1864 fprintf(stderr, "WARNING: setting ro.device_owner to a domain\n");
1865 static const char domain[] = "com.google.android.SecOps.DeviceOwner";
1866 EXPECT_NE(0, property_set(readonly_key, domain));
1867 useconds_t total_time = 0;
1868 static const useconds_t seconds = 1000000;
1869 static const useconds_t max_time = 5 * seconds; // not going to happen
1870 static const useconds_t rest = 20 * 1000;
1871 for (; total_time < max_time; total_time += rest) {
1872 usleep(rest); // property system does not guarantee performance.
1873 property_get(readonly_key, readonly, nothing_val);
1874 if (!strcmp(readonly, domain)) {
1875 if (total_time > rest) {
1876 fprintf(stderr, "INFO: took %u.%06u seconds to set property\n",
1877 (unsigned)(total_time / seconds),
1878 (unsigned)(total_time % seconds));
1879 }
1880 break;
1881 }
1882 }
1883 EXPECT_STRNE(domain, readonly);
1884 }
1885
1886 if (!strcasecmp(readonly, "false") || !readonly[0] ||
1887 !strcmp(readonly, nothing_val)) {
1888 // not enough permissions to run tests surrounding persist.logd.security
1889 EXPECT_FALSE(__android_log_security());
1890 return;
1891 }
1892
1893 if (!strcasecmp(persist, "true")) {
1894 EXPECT_TRUE(__android_log_security());
1895 } else {
1896 EXPECT_FALSE(__android_log_security());
1897 }
1898 property_set(persist_key, "TRUE");
1899 property_get(persist_key, persist, "");
1900 uid_t uid = getuid();
1901 gid_t gid = getgid();
1902 bool perm = (gid == AID_ROOT) || (uid == AID_ROOT);
1903 EXPECT_STREQ(perm ? "TRUE" : persist_hold, persist);
1904 if (!strcasecmp(persist, "true")) {
1905 EXPECT_TRUE(__android_log_security());
1906 } else {
1907 EXPECT_FALSE(__android_log_security());
1908 }
1909 property_set(persist_key, "FALSE");
1910 property_get(persist_key, persist, "");
1911 EXPECT_STREQ(perm ? "FALSE" : persist_hold, persist);
1912 if (!strcasecmp(persist, "true")) {
1913 EXPECT_TRUE(__android_log_security());
1914 } else {
1915 EXPECT_FALSE(__android_log_security());
1916 }
1917 property_set(persist_key, "true");
1918 property_get(persist_key, persist, "");
1919 EXPECT_STREQ(perm ? "true" : persist_hold, persist);
1920 if (!strcasecmp(persist, "true")) {
1921 EXPECT_TRUE(__android_log_security());
1922 } else {
1923 EXPECT_FALSE(__android_log_security());
1924 }
1925 property_set(persist_key, "false");
1926 property_get(persist_key, persist, "");
1927 EXPECT_STREQ(perm ? "false" : persist_hold, persist);
1928 if (!strcasecmp(persist, "true")) {
1929 EXPECT_TRUE(__android_log_security());
1930 } else {
1931 EXPECT_FALSE(__android_log_security());
1932 }
1933 property_set(persist_key, "");
1934 property_get(persist_key, persist, "");
1935 EXPECT_STREQ(perm ? "" : persist_hold, persist);
1936 if (!strcasecmp(persist, "true")) {
1937 EXPECT_TRUE(__android_log_security());
1938 } else {
1939 EXPECT_FALSE(__android_log_security());
1940 }
1941 property_set(persist_key, persist_hold);
1942 property_get(persist_key, persist, "");
1943 EXPECT_STREQ(persist_hold, persist);
1944 #else
1945 GTEST_LOG_(INFO) << "This test does nothing.\n";
1946 #endif
1947 }
1948
TEST(liblog,__security_buffer)1949 TEST(liblog, __security_buffer) {
1950 #ifdef __ANDROID__
1951 struct logger_list* logger_list;
1952 android_event_long_t buffer;
1953
1954 static const char persist_key[] = "persist.logd.security";
1955 char persist[PROP_VALUE_MAX];
1956 bool set_persist = false;
1957 bool allow_security = false;
1958
1959 if (__android_log_security()) {
1960 allow_security = true;
1961 } else {
1962 property_get(persist_key, persist, "");
1963 if (strcasecmp(persist, "true")) {
1964 property_set(persist_key, "TRUE");
1965 if (__android_log_security()) {
1966 allow_security = true;
1967 set_persist = true;
1968 } else {
1969 property_set(persist_key, persist);
1970 }
1971 }
1972 }
1973
1974 if (!allow_security) {
1975 fprintf(stderr,
1976 "WARNING: "
1977 "security buffer disabled, bypassing end-to-end test\n");
1978
1979 log_time ts(CLOCK_MONOTONIC);
1980
1981 buffer.type = EVENT_TYPE_LONG;
1982 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
1983
1984 // expect failure!
1985 ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
1986
1987 return;
1988 }
1989
1990 /* Matches clientHasLogCredentials() in logd */
1991 uid_t uid = getuid();
1992 gid_t gid = getgid();
1993 bool clientHasLogCredentials = true;
1994 if ((uid != AID_SYSTEM) && (uid != AID_ROOT) && (uid != AID_LOG) &&
1995 (gid != AID_SYSTEM) && (gid != AID_ROOT) && (gid != AID_LOG)) {
1996 uid_t euid = geteuid();
1997 if ((euid != AID_SYSTEM) && (euid != AID_ROOT) && (euid != AID_LOG)) {
1998 gid_t egid = getegid();
1999 if ((egid != AID_SYSTEM) && (egid != AID_ROOT) && (egid != AID_LOG)) {
2000 int num_groups = getgroups(0, NULL);
2001 if (num_groups > 0) {
2002 gid_t groups[num_groups];
2003 num_groups = getgroups(num_groups, groups);
2004 while (num_groups > 0) {
2005 if (groups[num_groups - 1] == AID_LOG) {
2006 break;
2007 }
2008 --num_groups;
2009 }
2010 }
2011 if (num_groups <= 0) {
2012 clientHasLogCredentials = false;
2013 }
2014 }
2015 }
2016 }
2017 if (!clientHasLogCredentials) {
2018 fprintf(stderr,
2019 "WARNING: "
2020 "not in system context, bypassing end-to-end test\n");
2021
2022 log_time ts(CLOCK_MONOTONIC);
2023
2024 buffer.type = EVENT_TYPE_LONG;
2025 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
2026
2027 // expect failure!
2028 ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
2029
2030 return;
2031 }
2032
2033 EXPECT_EQ(0, setuid(AID_SYSTEM)); // only one that can read security buffer
2034
2035 uid = getuid();
2036 gid = getgid();
2037 pid_t pid = getpid();
2038
2039 ASSERT_TRUE(NULL !=
2040 (logger_list = android_logger_list_open(
2041 LOG_ID_SECURITY, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
2042 1000, pid)));
2043
2044 log_time ts(CLOCK_MONOTONIC);
2045
2046 buffer.type = EVENT_TYPE_LONG;
2047 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
2048
2049 ASSERT_LT(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
2050 usleep(1000000);
2051
2052 int count = 0;
2053
2054 for (;;) {
2055 log_msg log_msg;
2056 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
2057 break;
2058 }
2059
2060 ASSERT_EQ(log_msg.entry.pid, pid);
2061
2062 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
2063 (log_msg.id() != LOG_ID_SECURITY)) {
2064 continue;
2065 }
2066
2067 android_log_event_long_t* eventData;
2068 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
2069
2070 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
2071 continue;
2072 }
2073
2074 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
2075 if (ts == tx) {
2076 ++count;
2077 }
2078 }
2079
2080 if (set_persist) {
2081 property_set(persist_key, persist);
2082 }
2083
2084 android_logger_list_close(logger_list);
2085
2086 bool clientHasSecurityCredentials = (uid == AID_SYSTEM) || (gid == AID_SYSTEM);
2087 if (!clientHasSecurityCredentials) {
2088 fprintf(stderr,
2089 "WARNING: "
2090 "not system, content submitted but can not check end-to-end\n");
2091 }
2092 EXPECT_EQ(clientHasSecurityCredentials ? 1 : 0, count);
2093 #else
2094 GTEST_LOG_(INFO) << "This test does nothing.\n";
2095 #endif
2096 }
2097 #endif // USING_LOGGER_DEFAULT
2098
2099 #ifdef TEST_PREFIX
android_errorWriteWithInfoLog_helper(int TAG,const char * SUBTAG,int UID,const char * payload,int DATA_LEN,int & count)2100 static void android_errorWriteWithInfoLog_helper(int TAG, const char* SUBTAG,
2101 int UID, const char* payload,
2102 int DATA_LEN, int& count) {
2103 TEST_PREFIX
2104 struct logger_list* logger_list;
2105
2106 pid_t pid = getpid();
2107
2108 count = 0;
2109
2110 ASSERT_TRUE(NULL !=
2111 (logger_list = android_logger_list_open(
2112 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
2113 1000, pid)));
2114
2115 int retval_android_errorWriteWithinInfoLog =
2116 android_errorWriteWithInfoLog(TAG, SUBTAG, UID, payload, DATA_LEN);
2117 if (payload) {
2118 ASSERT_LT(0, retval_android_errorWriteWithinInfoLog);
2119 } else {
2120 ASSERT_GT(0, retval_android_errorWriteWithinInfoLog);
2121 }
2122
2123 sleep(2);
2124
2125 for (;;) {
2126 log_msg log_msg;
2127 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
2128 break;
2129 }
2130
2131 char* eventData = log_msg.msg();
2132 if (!eventData) {
2133 continue;
2134 }
2135
2136 char* original = eventData;
2137
2138 // Tag
2139 int tag = get4LE(eventData);
2140 eventData += 4;
2141
2142 if (tag != TAG) {
2143 continue;
2144 }
2145
2146 if (!payload) {
2147 // This tag should not have been written because the data was null
2148 ++count;
2149 break;
2150 }
2151
2152 // List type
2153 ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]);
2154 eventData++;
2155
2156 // Number of elements in list
2157 ASSERT_EQ(3, eventData[0]);
2158 eventData++;
2159
2160 // Element #1: string type for subtag
2161 ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]);
2162 eventData++;
2163
2164 unsigned subtag_len = strlen(SUBTAG);
2165 if (subtag_len > 32) subtag_len = 32;
2166 ASSERT_EQ(subtag_len, get4LE(eventData));
2167 eventData += 4;
2168
2169 if (memcmp(SUBTAG, eventData, subtag_len)) {
2170 continue;
2171 }
2172 eventData += subtag_len;
2173
2174 // Element #2: int type for uid
2175 ASSERT_EQ(EVENT_TYPE_INT, eventData[0]);
2176 eventData++;
2177
2178 ASSERT_EQ(UID, (int)get4LE(eventData));
2179 eventData += 4;
2180
2181 // Element #3: string type for data
2182 ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]);
2183 eventData++;
2184
2185 size_t dataLen = get4LE(eventData);
2186 eventData += 4;
2187 if (DATA_LEN < 512) ASSERT_EQ(DATA_LEN, (int)dataLen);
2188
2189 if (memcmp(payload, eventData, dataLen)) {
2190 continue;
2191 }
2192
2193 if (DATA_LEN >= 512) {
2194 eventData += dataLen;
2195 // 4 bytes for the tag, and max_payload_buf should be truncated.
2196 ASSERT_LE(4 + 512, eventData - original); // worst expectations
2197 ASSERT_GT(4 + DATA_LEN, eventData - original); // must be truncated
2198 }
2199
2200 ++count;
2201 }
2202
2203 android_logger_list_close(logger_list);
2204 }
2205 #endif
2206
2207 // Make multiple tests and re-tests orthogonal to prevent falsing.
2208 #ifdef TEST_LOGGER
2209 #define UNIQUE_TAG(X) \
2210 (0x12340000 + (((X) + sizeof(int) + sizeof(void*)) << 8) + TEST_LOGGER)
2211 #else
2212 #define UNIQUE_TAG(X) \
2213 (0x12340000 + (((X) + sizeof(int) + sizeof(void*)) << 8) + 0xBA)
2214 #endif
2215
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__typical)2216 TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__typical) {
2217 #ifdef TEST_PREFIX
2218 int count;
2219 android_errorWriteWithInfoLog_helper(UNIQUE_TAG(1), "test-subtag", -1,
2220 max_payload_buf, 200, count);
2221 EXPECT_EQ(SUPPORTS_END_TO_END, count);
2222 #else
2223 GTEST_LOG_(INFO) << "This test does nothing.\n";
2224 #endif
2225 }
2226
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__data_too_large)2227 TEST(liblog,
2228 android_errorWriteWithInfoLog__android_logger_list_read__data_too_large) {
2229 #ifdef TEST_PREFIX
2230 int count;
2231 android_errorWriteWithInfoLog_helper(UNIQUE_TAG(2), "test-subtag", -1,
2232 max_payload_buf, sizeof(max_payload_buf),
2233 count);
2234 EXPECT_EQ(SUPPORTS_END_TO_END, count);
2235 #else
2236 GTEST_LOG_(INFO) << "This test does nothing.\n";
2237 #endif
2238 }
2239
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__null_data)2240 TEST(liblog,
2241 android_errorWriteWithInfoLog__android_logger_list_read__null_data) {
2242 #ifdef TEST_PREFIX
2243 int count;
2244 android_errorWriteWithInfoLog_helper(UNIQUE_TAG(3), "test-subtag", -1, NULL,
2245 200, count);
2246 EXPECT_EQ(0, count);
2247 #else
2248 GTEST_LOG_(INFO) << "This test does nothing.\n";
2249 #endif
2250 }
2251
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long)2252 TEST(liblog,
2253 android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long) {
2254 #ifdef TEST_PREFIX
2255 int count;
2256 android_errorWriteWithInfoLog_helper(
2257 UNIQUE_TAG(4), "abcdefghijklmnopqrstuvwxyz now i know my abc", -1,
2258 max_payload_buf, 200, count);
2259 EXPECT_EQ(SUPPORTS_END_TO_END, count);
2260 #else
2261 GTEST_LOG_(INFO) << "This test does nothing.\n";
2262 #endif
2263 }
2264
TEST(liblog,__android_log_bswrite_and_print___max)2265 TEST(liblog, __android_log_bswrite_and_print___max) {
2266 bswrite_test(max_payload_buf);
2267 }
2268
TEST(liblog,__android_log_buf_write_and_print__max)2269 TEST(liblog, __android_log_buf_write_and_print__max) {
2270 buf_write_test(max_payload_buf);
2271 }
2272
2273 #ifdef TEST_PREFIX
android_errorWriteLog_helper(int TAG,const char * SUBTAG,int & count)2274 static void android_errorWriteLog_helper(int TAG, const char* SUBTAG,
2275 int& count) {
2276 TEST_PREFIX
2277 struct logger_list* logger_list;
2278
2279 pid_t pid = getpid();
2280
2281 count = 0;
2282
2283 // Do a Before and After on the count to measure the effect. Decrement
2284 // what we find in Before to set the stage.
2285 ASSERT_TRUE(NULL !=
2286 (logger_list = android_logger_list_open(
2287 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
2288 1000, pid)));
2289
2290 for (;;) {
2291 log_msg log_msg;
2292 if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
2293
2294 char* eventData = log_msg.msg();
2295 if (!eventData) continue;
2296
2297 // Tag
2298 int tag = get4LE(eventData);
2299 eventData += 4;
2300
2301 if (tag != TAG) continue;
2302
2303 if (!SUBTAG) {
2304 // This tag should not have been written because the data was null
2305 --count;
2306 break;
2307 }
2308
2309 // List type
2310 eventData++;
2311 // Number of elements in list
2312 eventData++;
2313 // Element #1: string type for subtag
2314 eventData++;
2315
2316 eventData += 4;
2317
2318 if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) continue;
2319 --count;
2320 }
2321
2322 android_logger_list_close(logger_list);
2323
2324 // Do an After on the count to measure the effect.
2325 ASSERT_TRUE(NULL !=
2326 (logger_list = android_logger_list_open(
2327 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
2328 1000, pid)));
2329
2330 int retval_android_errorWriteLog = android_errorWriteLog(TAG, SUBTAG);
2331 if (SUBTAG) {
2332 ASSERT_LT(0, retval_android_errorWriteLog);
2333 } else {
2334 ASSERT_GT(0, retval_android_errorWriteLog);
2335 }
2336
2337 sleep(2);
2338
2339 for (;;) {
2340 log_msg log_msg;
2341 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
2342 break;
2343 }
2344
2345 char* eventData = log_msg.msg();
2346 if (!eventData) {
2347 continue;
2348 }
2349
2350 // Tag
2351 int tag = get4LE(eventData);
2352 eventData += 4;
2353
2354 if (tag != TAG) {
2355 continue;
2356 }
2357
2358 if (!SUBTAG) {
2359 // This tag should not have been written because the data was null
2360 ++count;
2361 break;
2362 }
2363
2364 // List type
2365 ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]);
2366 eventData++;
2367
2368 // Number of elements in list
2369 ASSERT_EQ(3, eventData[0]);
2370 eventData++;
2371
2372 // Element #1: string type for subtag
2373 ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]);
2374 eventData++;
2375
2376 ASSERT_EQ(strlen(SUBTAG), get4LE(eventData));
2377 eventData += 4;
2378
2379 if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) {
2380 continue;
2381 }
2382 ++count;
2383 }
2384
2385 android_logger_list_close(logger_list);
2386 }
2387 #endif
2388
TEST(liblog,android_errorWriteLog__android_logger_list_read__success)2389 TEST(liblog, android_errorWriteLog__android_logger_list_read__success) {
2390 #ifdef TEST_PREFIX
2391 int count;
2392 android_errorWriteLog_helper(UNIQUE_TAG(5), "test-subtag", count);
2393 EXPECT_EQ(SUPPORTS_END_TO_END, count);
2394 #else
2395 GTEST_LOG_(INFO) << "This test does nothing.\n";
2396 #endif
2397 }
2398
TEST(liblog,android_errorWriteLog__android_logger_list_read__null_subtag)2399 TEST(liblog, android_errorWriteLog__android_logger_list_read__null_subtag) {
2400 #ifdef TEST_PREFIX
2401 int count;
2402 android_errorWriteLog_helper(UNIQUE_TAG(6), NULL, count);
2403 EXPECT_EQ(0, count);
2404 #else
2405 GTEST_LOG_(INFO) << "This test does nothing.\n";
2406 #endif
2407 }
2408
2409 // Do not retest logger list handling
2410 #if (defined(TEST_PREFIX) || !defined(USING_LOGGER_LOCAL))
is_real_element(int type)2411 static int is_real_element(int type) {
2412 return ((type == EVENT_TYPE_INT) || (type == EVENT_TYPE_LONG) ||
2413 (type == EVENT_TYPE_STRING) || (type == EVENT_TYPE_FLOAT));
2414 }
2415
android_log_buffer_to_string(const char * msg,size_t len,char * strOut,size_t strOutLen)2416 static int android_log_buffer_to_string(const char* msg, size_t len,
2417 char* strOut, size_t strOutLen) {
2418 android_log_context context = create_android_log_parser(msg, len);
2419 android_log_list_element elem;
2420 bool overflow = false;
2421 /* Reserve 1 byte for null terminator. */
2422 size_t origStrOutLen = strOutLen--;
2423
2424 if (!context) {
2425 return -EBADF;
2426 }
2427
2428 memset(&elem, 0, sizeof(elem));
2429
2430 size_t outCount;
2431
2432 do {
2433 elem = android_log_read_next(context);
2434 switch ((int)elem.type) {
2435 case EVENT_TYPE_LIST:
2436 if (strOutLen == 0) {
2437 overflow = true;
2438 } else {
2439 *strOut++ = '[';
2440 strOutLen--;
2441 }
2442 break;
2443
2444 case EVENT_TYPE_LIST_STOP:
2445 if (strOutLen == 0) {
2446 overflow = true;
2447 } else {
2448 *strOut++ = ']';
2449 strOutLen--;
2450 }
2451 break;
2452
2453 case EVENT_TYPE_INT:
2454 /*
2455 * snprintf also requires room for the null terminator, which
2456 * we don't care about but we have allocated enough room for
2457 * that
2458 */
2459 outCount = snprintf(strOut, strOutLen + 1, "%" PRId32, elem.data.int32);
2460 if (outCount <= strOutLen) {
2461 strOut += outCount;
2462 strOutLen -= outCount;
2463 } else {
2464 overflow = true;
2465 }
2466 break;
2467
2468 case EVENT_TYPE_LONG:
2469 /*
2470 * snprintf also requires room for the null terminator, which
2471 * we don't care about but we have allocated enough room for
2472 * that
2473 */
2474 outCount = snprintf(strOut, strOutLen + 1, "%" PRId64, elem.data.int64);
2475 if (outCount <= strOutLen) {
2476 strOut += outCount;
2477 strOutLen -= outCount;
2478 } else {
2479 overflow = true;
2480 }
2481 break;
2482
2483 case EVENT_TYPE_FLOAT:
2484 /*
2485 * snprintf also requires room for the null terminator, which
2486 * we don't care about but we have allocated enough room for
2487 * that
2488 */
2489 outCount = snprintf(strOut, strOutLen + 1, "%f", elem.data.float32);
2490 if (outCount <= strOutLen) {
2491 strOut += outCount;
2492 strOutLen -= outCount;
2493 } else {
2494 overflow = true;
2495 }
2496 break;
2497
2498 default:
2499 elem.complete = true;
2500 break;
2501
2502 case EVENT_TYPE_UNKNOWN:
2503 #if 0 // Ideal purity in the test, we want to complain about UNKNOWN showing up
2504 if (elem.complete) {
2505 break;
2506 }
2507 #endif
2508 elem.data.string = const_cast<char*>("<unknown>");
2509 elem.len = strlen(elem.data.string);
2510 /* FALLTHRU */
2511 case EVENT_TYPE_STRING:
2512 if (elem.len <= strOutLen) {
2513 memcpy(strOut, elem.data.string, elem.len);
2514 strOut += elem.len;
2515 strOutLen -= elem.len;
2516 } else if (strOutLen > 0) {
2517 /* copy what we can */
2518 memcpy(strOut, elem.data.string, strOutLen);
2519 strOut += strOutLen;
2520 strOutLen = 0;
2521 overflow = true;
2522 }
2523 break;
2524 }
2525
2526 if (elem.complete) {
2527 break;
2528 }
2529 /* Determine whether to put a comma or not. */
2530 if (!overflow &&
2531 (is_real_element(elem.type) || (elem.type == EVENT_TYPE_LIST_STOP))) {
2532 android_log_list_element next = android_log_peek_next(context);
2533 if (!next.complete &&
2534 (is_real_element(next.type) || (next.type == EVENT_TYPE_LIST))) {
2535 if (strOutLen == 0) {
2536 overflow = true;
2537 } else {
2538 *strOut++ = ',';
2539 strOutLen--;
2540 }
2541 }
2542 }
2543 } while ((elem.type != EVENT_TYPE_UNKNOWN) && !overflow && !elem.complete);
2544
2545 android_log_destroy(&context);
2546
2547 if (overflow) {
2548 if (strOutLen < origStrOutLen) {
2549 /* leave an indicator */
2550 *(strOut - 1) = '!';
2551 } else {
2552 /* nothing was written at all */
2553 *strOut++ = '!';
2554 }
2555 }
2556 *strOut++ = '\0';
2557
2558 if ((elem.type == EVENT_TYPE_UNKNOWN) && !elem.complete) {
2559 fprintf(stderr, "Binary log entry conversion failed\n");
2560 return -EINVAL;
2561 }
2562
2563 return 0;
2564 }
2565 #endif // TEST_PREFIX || !USING_LOGGER_LOCAL
2566
2567 #ifdef TEST_PREFIX
event_test_int32(uint32_t tag,size_t & expected_len)2568 static const char* event_test_int32(uint32_t tag, size_t& expected_len) {
2569 android_log_context ctx;
2570
2571 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2572 if (!ctx) {
2573 return NULL;
2574 }
2575 EXPECT_LE(0, android_log_write_int32(ctx, 0x40302010));
2576 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2577 EXPECT_LE(0, android_log_destroy(&ctx));
2578 EXPECT_TRUE(NULL == ctx);
2579
2580 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint32_t);
2581
2582 return "1076895760";
2583 }
2584
event_test_int64(uint32_t tag,size_t & expected_len)2585 static const char* event_test_int64(uint32_t tag, size_t& expected_len) {
2586 android_log_context ctx;
2587
2588 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2589 if (!ctx) {
2590 return NULL;
2591 }
2592 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2593 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2594 EXPECT_LE(0, android_log_destroy(&ctx));
2595 EXPECT_TRUE(NULL == ctx);
2596
2597 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint64_t);
2598
2599 return "-9191740941672636400";
2600 }
2601
event_test_list_int64(uint32_t tag,size_t & expected_len)2602 static const char* event_test_list_int64(uint32_t tag, size_t& expected_len) {
2603 android_log_context ctx;
2604
2605 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2606 if (!ctx) {
2607 return NULL;
2608 }
2609 EXPECT_LE(0, android_log_write_list_begin(ctx));
2610 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2611 EXPECT_LE(0, android_log_write_list_end(ctx));
2612 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2613 EXPECT_LE(0, android_log_destroy(&ctx));
2614 EXPECT_TRUE(NULL == ctx);
2615
2616 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2617 sizeof(uint8_t) + sizeof(uint64_t);
2618
2619 return "[-9191740941672636400]";
2620 }
2621
event_test_simple_automagic_list(uint32_t tag,size_t & expected_len)2622 static const char* event_test_simple_automagic_list(uint32_t tag,
2623 size_t& expected_len) {
2624 android_log_context ctx;
2625
2626 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2627 if (!ctx) {
2628 return NULL;
2629 }
2630 // The convenience API where we allow a simple list to be
2631 // created without explicit begin or end calls.
2632 EXPECT_LE(0, android_log_write_int32(ctx, 0x40302010));
2633 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2634 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2635 EXPECT_LE(0, android_log_destroy(&ctx));
2636 EXPECT_TRUE(NULL == ctx);
2637
2638 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2639 sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2640 sizeof(uint64_t);
2641
2642 return "[1076895760,-9191740941672636400]";
2643 }
2644
event_test_list_empty(uint32_t tag,size_t & expected_len)2645 static const char* event_test_list_empty(uint32_t tag, size_t& expected_len) {
2646 android_log_context ctx;
2647
2648 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2649 if (!ctx) {
2650 return NULL;
2651 }
2652 EXPECT_LE(0, android_log_write_list_begin(ctx));
2653 EXPECT_LE(0, android_log_write_list_end(ctx));
2654 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2655 EXPECT_LE(0, android_log_destroy(&ctx));
2656 EXPECT_TRUE(NULL == ctx);
2657
2658 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t);
2659
2660 return "[]";
2661 }
2662
event_test_complex_nested_list(uint32_t tag,size_t & expected_len)2663 static const char* event_test_complex_nested_list(uint32_t tag,
2664 size_t& expected_len) {
2665 android_log_context ctx;
2666
2667 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2668 if (!ctx) {
2669 return NULL;
2670 }
2671
2672 EXPECT_LE(0, android_log_write_list_begin(ctx)); // [
2673 EXPECT_LE(0, android_log_write_int32(ctx, 0x01020304));
2674 EXPECT_LE(0, android_log_write_int64(ctx, 0x0102030405060708));
2675 EXPECT_LE(0, android_log_write_string8(ctx, "Hello World"));
2676 EXPECT_LE(0, android_log_write_list_begin(ctx)); // [
2677 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2678 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2679 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2680 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2681 EXPECT_LE(0, android_log_write_list_end(ctx)); // ]
2682 EXPECT_LE(0, android_log_write_float32(ctx, 1.0102030405060708));
2683 EXPECT_LE(0, android_log_write_list_end(ctx)); // ]
2684
2685 //
2686 // This one checks for the automagic list creation because a list
2687 // begin and end was missing for it! This is actually an <oops> corner
2688 // case, and not the behavior we morally support. The automagic API is to
2689 // allow for a simple case of a series of objects in a single list. e.g.
2690 // int32,int32,int32,string -> [int32,int32,int32,string]
2691 //
2692 EXPECT_LE(0, android_log_write_string8(ctx, "dlroW olleH"));
2693
2694 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2695 EXPECT_LE(0, android_log_destroy(&ctx));
2696 EXPECT_TRUE(NULL == ctx);
2697
2698 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2699 sizeof(uint8_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2700 sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint64_t) +
2701 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2702 1 + sizeof(uint8_t) + sizeof(uint8_t) +
2703 4 * (sizeof(uint8_t) + sizeof(uint32_t)) + sizeof(uint8_t) +
2704 sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint32_t) +
2705 sizeof("dlroW olleH") - 1;
2706
2707 return "[[16909060,72623859790382856,Hello World,[1,2,3,4],1.010203],dlroW "
2708 "olleH]";
2709 }
2710
event_test_7_level_prefix(uint32_t tag,size_t & expected_len)2711 static const char* event_test_7_level_prefix(uint32_t tag,
2712 size_t& expected_len) {
2713 android_log_context ctx;
2714
2715 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2716 if (!ctx) {
2717 return NULL;
2718 }
2719 EXPECT_LE(0, android_log_write_list_begin(ctx));
2720 EXPECT_LE(0, android_log_write_list_begin(ctx));
2721 EXPECT_LE(0, android_log_write_list_begin(ctx));
2722 EXPECT_LE(0, android_log_write_list_begin(ctx));
2723 EXPECT_LE(0, android_log_write_list_begin(ctx));
2724 EXPECT_LE(0, android_log_write_list_begin(ctx));
2725 EXPECT_LE(0, android_log_write_list_begin(ctx));
2726 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2727 EXPECT_LE(0, android_log_write_list_end(ctx));
2728 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2729 EXPECT_LE(0, android_log_write_list_end(ctx));
2730 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2731 EXPECT_LE(0, android_log_write_list_end(ctx));
2732 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2733 EXPECT_LE(0, android_log_write_list_end(ctx));
2734 EXPECT_LE(0, android_log_write_int32(ctx, 5));
2735 EXPECT_LE(0, android_log_write_list_end(ctx));
2736 EXPECT_LE(0, android_log_write_int32(ctx, 6));
2737 EXPECT_LE(0, android_log_write_list_end(ctx));
2738 EXPECT_LE(0, android_log_write_int32(ctx, 7));
2739 EXPECT_LE(0, android_log_write_list_end(ctx));
2740 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2741 EXPECT_LE(0, android_log_destroy(&ctx));
2742 EXPECT_TRUE(NULL == ctx);
2743
2744 expected_len = sizeof(uint32_t) + 7 * (sizeof(uint8_t) + sizeof(uint8_t) +
2745 sizeof(uint8_t) + sizeof(uint32_t));
2746
2747 return "[[[[[[[1],2],3],4],5],6],7]";
2748 }
2749
event_test_7_level_suffix(uint32_t tag,size_t & expected_len)2750 static const char* event_test_7_level_suffix(uint32_t tag,
2751 size_t& expected_len) {
2752 android_log_context ctx;
2753
2754 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2755 if (!ctx) {
2756 return NULL;
2757 }
2758 EXPECT_LE(0, android_log_write_list_begin(ctx));
2759 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2760 EXPECT_LE(0, android_log_write_list_begin(ctx));
2761 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2762 EXPECT_LE(0, android_log_write_list_begin(ctx));
2763 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2764 EXPECT_LE(0, android_log_write_list_begin(ctx));
2765 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2766 EXPECT_LE(0, android_log_write_list_begin(ctx));
2767 EXPECT_LE(0, android_log_write_int32(ctx, 5));
2768 EXPECT_LE(0, android_log_write_list_begin(ctx));
2769 EXPECT_LE(0, android_log_write_int32(ctx, 6));
2770 EXPECT_LE(0, android_log_write_list_end(ctx));
2771 EXPECT_LE(0, android_log_write_list_end(ctx));
2772 EXPECT_LE(0, android_log_write_list_end(ctx));
2773 EXPECT_LE(0, android_log_write_list_end(ctx));
2774 EXPECT_LE(0, android_log_write_list_end(ctx));
2775 EXPECT_LE(0, android_log_write_list_end(ctx));
2776 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2777 EXPECT_LE(0, android_log_destroy(&ctx));
2778 EXPECT_TRUE(NULL == ctx);
2779
2780 expected_len = sizeof(uint32_t) + 6 * (sizeof(uint8_t) + sizeof(uint8_t) +
2781 sizeof(uint8_t) + sizeof(uint32_t));
2782
2783 return "[1,[2,[3,[4,[5,[6]]]]]]";
2784 }
2785
event_test_android_log_error_write(uint32_t tag,size_t & expected_len)2786 static const char* event_test_android_log_error_write(uint32_t tag,
2787 size_t& expected_len) {
2788 EXPECT_LE(
2789 0, __android_log_error_write(tag, "Hello World", 42, "dlroW olleH", 11));
2790
2791 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2792 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2793 1 + sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2794 sizeof(uint32_t) + sizeof("dlroW olleH") - 1;
2795
2796 return "[Hello World,42,dlroW olleH]";
2797 }
2798
event_test_android_log_error_write_null(uint32_t tag,size_t & expected_len)2799 static const char* event_test_android_log_error_write_null(uint32_t tag,
2800 size_t& expected_len) {
2801 EXPECT_LE(0, __android_log_error_write(tag, "Hello World", 42, NULL, 0));
2802
2803 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2804 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2805 1 + sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2806 sizeof(uint32_t) + sizeof("") - 1;
2807
2808 return "[Hello World,42,]";
2809 }
2810
2811 // make sure all user buffers are flushed
print_barrier()2812 static void print_barrier() {
2813 std::cout.flush();
2814 fflush(stdout);
2815 std::cerr.flush();
2816 fflush(stderr); // everything else is paranoia ...
2817 }
2818
create_android_logger(const char * (* fn)(uint32_t tag,size_t & expected_len))2819 static void create_android_logger(const char* (*fn)(uint32_t tag,
2820 size_t& expected_len)) {
2821 TEST_PREFIX
2822 struct logger_list* logger_list;
2823
2824 pid_t pid = getpid();
2825
2826 ASSERT_TRUE(NULL !=
2827 (logger_list = android_logger_list_open(
2828 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
2829 1000, pid)));
2830
2831 #ifdef __ANDROID__
2832 log_time ts(android_log_clockid());
2833 #else
2834 log_time ts(CLOCK_REALTIME);
2835 #endif
2836
2837 size_t expected_len;
2838 const char* expected_string = (*fn)(1005, expected_len);
2839
2840 if (!expected_string) {
2841 android_logger_list_close(logger_list);
2842 return;
2843 }
2844
2845 usleep(1000000);
2846
2847 int count = 0;
2848
2849 for (;;) {
2850 log_msg log_msg;
2851 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
2852 break;
2853 }
2854
2855 ASSERT_EQ(log_msg.entry.pid, pid);
2856
2857 if ((log_msg.entry.sec < (ts.tv_sec - 1)) ||
2858 ((ts.tv_sec + 1) < log_msg.entry.sec) ||
2859 ((size_t)log_msg.entry.len != expected_len) ||
2860 (log_msg.id() != LOG_ID_EVENTS)) {
2861 continue;
2862 }
2863
2864 char* eventData = log_msg.msg();
2865
2866 ++count;
2867
2868 AndroidLogFormat* logformat = android_log_format_new();
2869 EXPECT_TRUE(NULL != logformat);
2870 AndroidLogEntry entry;
2871 char msgBuf[1024];
2872 int processBinaryLogBuffer = android_log_processBinaryLogBuffer(
2873 &log_msg.entry_v1, &entry, NULL, msgBuf, sizeof(msgBuf));
2874 EXPECT_EQ(0, processBinaryLogBuffer);
2875 if (processBinaryLogBuffer == 0) {
2876 int line_overhead = 20;
2877 if (pid > 99999) ++line_overhead;
2878 if (pid > 999999) ++line_overhead;
2879 print_barrier();
2880 int printLogLine =
2881 android_log_printLogLine(logformat, fileno(stderr), &entry);
2882 print_barrier();
2883 EXPECT_EQ(line_overhead + (int)strlen(expected_string), printLogLine);
2884 }
2885 android_log_format_free(logformat);
2886
2887 // test buffer reading API
2888 int buffer_to_string = -1;
2889 if (eventData) {
2890 snprintf(msgBuf, sizeof(msgBuf), "I/[%" PRIu32 "]", get4LE(eventData));
2891 print_barrier();
2892 fprintf(stderr, "%-10s(%5u): ", msgBuf, pid);
2893 memset(msgBuf, 0, sizeof(msgBuf));
2894 buffer_to_string = android_log_buffer_to_string(
2895 eventData + sizeof(uint32_t), log_msg.entry.len - sizeof(uint32_t),
2896 msgBuf, sizeof(msgBuf));
2897 fprintf(stderr, "%s\n", msgBuf);
2898 print_barrier();
2899 }
2900 EXPECT_EQ(0, buffer_to_string);
2901 EXPECT_EQ(strlen(expected_string), strlen(msgBuf));
2902 EXPECT_EQ(0, strcmp(expected_string, msgBuf));
2903 }
2904
2905 EXPECT_EQ(SUPPORTS_END_TO_END, count);
2906
2907 android_logger_list_close(logger_list);
2908 }
2909 #endif
2910
TEST(liblog,create_android_logger_int32)2911 TEST(liblog, create_android_logger_int32) {
2912 #ifdef TEST_PREFIX
2913 create_android_logger(event_test_int32);
2914 #else
2915 GTEST_LOG_(INFO) << "This test does nothing.\n";
2916 #endif
2917 }
2918
TEST(liblog,create_android_logger_int64)2919 TEST(liblog, create_android_logger_int64) {
2920 #ifdef TEST_PREFIX
2921 create_android_logger(event_test_int64);
2922 #else
2923 GTEST_LOG_(INFO) << "This test does nothing.\n";
2924 #endif
2925 }
2926
TEST(liblog,create_android_logger_list_int64)2927 TEST(liblog, create_android_logger_list_int64) {
2928 #ifdef TEST_PREFIX
2929 create_android_logger(event_test_list_int64);
2930 #else
2931 GTEST_LOG_(INFO) << "This test does nothing.\n";
2932 #endif
2933 }
2934
TEST(liblog,create_android_logger_simple_automagic_list)2935 TEST(liblog, create_android_logger_simple_automagic_list) {
2936 #ifdef TEST_PREFIX
2937 create_android_logger(event_test_simple_automagic_list);
2938 #else
2939 GTEST_LOG_(INFO) << "This test does nothing.\n";
2940 #endif
2941 }
2942
TEST(liblog,create_android_logger_list_empty)2943 TEST(liblog, create_android_logger_list_empty) {
2944 #ifdef TEST_PREFIX
2945 create_android_logger(event_test_list_empty);
2946 #else
2947 GTEST_LOG_(INFO) << "This test does nothing.\n";
2948 #endif
2949 }
2950
TEST(liblog,create_android_logger_complex_nested_list)2951 TEST(liblog, create_android_logger_complex_nested_list) {
2952 #ifdef TEST_PREFIX
2953 create_android_logger(event_test_complex_nested_list);
2954 #else
2955 GTEST_LOG_(INFO) << "This test does nothing.\n";
2956 #endif
2957 }
2958
TEST(liblog,create_android_logger_7_level_prefix)2959 TEST(liblog, create_android_logger_7_level_prefix) {
2960 #ifdef TEST_PREFIX
2961 create_android_logger(event_test_7_level_prefix);
2962 #else
2963 GTEST_LOG_(INFO) << "This test does nothing.\n";
2964 #endif
2965 }
2966
TEST(liblog,create_android_logger_7_level_suffix)2967 TEST(liblog, create_android_logger_7_level_suffix) {
2968 #ifdef TEST_PREFIX
2969 create_android_logger(event_test_7_level_suffix);
2970 #else
2971 GTEST_LOG_(INFO) << "This test does nothing.\n";
2972 #endif
2973 }
2974
TEST(liblog,create_android_logger_android_log_error_write)2975 TEST(liblog, create_android_logger_android_log_error_write) {
2976 #ifdef TEST_PREFIX
2977 create_android_logger(event_test_android_log_error_write);
2978 #else
2979 GTEST_LOG_(INFO) << "This test does nothing.\n";
2980 #endif
2981 }
2982
TEST(liblog,create_android_logger_android_log_error_write_null)2983 TEST(liblog, create_android_logger_android_log_error_write_null) {
2984 #ifdef TEST_PREFIX
2985 create_android_logger(event_test_android_log_error_write_null);
2986 #else
2987 GTEST_LOG_(INFO) << "This test does nothing.\n";
2988 #endif
2989 }
2990
2991 #ifdef USING_LOGGER_DEFAULT // Do not retest logger list handling
TEST(liblog,create_android_logger_overflow)2992 TEST(liblog, create_android_logger_overflow) {
2993 android_log_context ctx;
2994
2995 EXPECT_TRUE(NULL != (ctx = create_android_logger(1005)));
2996 if (ctx) {
2997 for (size_t i = 0; i < ANDROID_MAX_LIST_NEST_DEPTH; ++i) {
2998 EXPECT_LE(0, android_log_write_list_begin(ctx));
2999 }
3000 EXPECT_GT(0, android_log_write_list_begin(ctx));
3001 /* One more for good measure, must be permanently unhappy */
3002 EXPECT_GT(0, android_log_write_list_begin(ctx));
3003 EXPECT_LE(0, android_log_destroy(&ctx));
3004 EXPECT_TRUE(NULL == ctx);
3005 }
3006
3007 ASSERT_TRUE(NULL != (ctx = create_android_logger(1005)));
3008 for (size_t i = 0; i < ANDROID_MAX_LIST_NEST_DEPTH; ++i) {
3009 EXPECT_LE(0, android_log_write_list_begin(ctx));
3010 EXPECT_LE(0, android_log_write_int32(ctx, i));
3011 }
3012 EXPECT_GT(0, android_log_write_list_begin(ctx));
3013 /* One more for good measure, must be permanently unhappy */
3014 EXPECT_GT(0, android_log_write_list_begin(ctx));
3015 EXPECT_LE(0, android_log_destroy(&ctx));
3016 ASSERT_TRUE(NULL == ctx);
3017 }
3018
TEST(liblog,android_log_write_list_buffer)3019 TEST(liblog, android_log_write_list_buffer) {
3020 __android_log_event_list ctx(1005);
3021 ctx << 1005 << "tag_def"
3022 << "(tag|1),(name|3),(format|3)";
3023 std::string buffer(ctx);
3024 ctx.close();
3025
3026 char msgBuf[1024];
3027 memset(msgBuf, 0, sizeof(msgBuf));
3028 EXPECT_EQ(android_log_buffer_to_string(buffer.data(), buffer.length(), msgBuf,
3029 sizeof(msgBuf)),
3030 0);
3031 EXPECT_STREQ(msgBuf, "[1005,tag_def,(tag|1),(name|3),(format|3)]");
3032 }
3033 #endif // USING_LOGGER_DEFAULT
3034
3035 #ifdef USING_LOGGER_DEFAULT // Do not retest pmsg functionality
3036 #ifdef __ANDROID__
3037 static const char __pmsg_file[] =
3038 "/data/william-shakespeare/MuchAdoAboutNothing.txt";
3039 #endif
3040
TEST(liblog,__android_log_pmsg_file_write)3041 TEST(liblog, __android_log_pmsg_file_write) {
3042 #ifdef __ANDROID__
3043 __android_log_close();
3044 if (getuid() == AID_ROOT) {
3045 tested__android_log_close = true;
3046 bool pmsgActiveAfter__android_log_close = isPmsgActive();
3047 bool logdwActiveAfter__android_log_close = isLogdwActive();
3048 EXPECT_FALSE(pmsgActiveAfter__android_log_close);
3049 EXPECT_FALSE(logdwActiveAfter__android_log_close);
3050 } else if (!tested__android_log_close) {
3051 fprintf(stderr, "WARNING: can not test __android_log_close()\n");
3052 }
3053 int return__android_log_pmsg_file_write = __android_log_pmsg_file_write(
3054 LOG_ID_CRASH, ANDROID_LOG_VERBOSE, __pmsg_file, max_payload_buf,
3055 sizeof(max_payload_buf));
3056 EXPECT_LT(0, return__android_log_pmsg_file_write);
3057 if (return__android_log_pmsg_file_write == -ENOMEM) {
3058 fprintf(stderr,
3059 "Kernel does not have space allocated to pmsg pstore driver "
3060 "configured\n");
3061 } else if (!return__android_log_pmsg_file_write) {
3062 fprintf(stderr,
3063 "Reboot, ensure file %s matches\n"
3064 "with liblog.__android_log_msg_file_read test\n",
3065 __pmsg_file);
3066 }
3067 bool pmsgActiveAfter__android_pmsg_file_write;
3068 bool logdwActiveAfter__android_pmsg_file_write;
3069 if (getuid() == AID_ROOT) {
3070 pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
3071 logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
3072 EXPECT_FALSE(pmsgActiveAfter__android_pmsg_file_write);
3073 EXPECT_FALSE(logdwActiveAfter__android_pmsg_file_write);
3074 }
3075 EXPECT_LT(
3076 0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
3077 "TEST__android_log_pmsg_file_write", "main"));
3078 if (getuid() == AID_ROOT) {
3079 bool pmsgActiveAfter__android_log_buf_print = isPmsgActive();
3080 bool logdwActiveAfter__android_log_buf_print = isLogdwActive();
3081 EXPECT_TRUE(pmsgActiveAfter__android_log_buf_print);
3082 EXPECT_TRUE(logdwActiveAfter__android_log_buf_print);
3083 }
3084 EXPECT_LT(0, __android_log_pmsg_file_write(LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
3085 __pmsg_file, max_payload_buf,
3086 sizeof(max_payload_buf)));
3087 if (getuid() == AID_ROOT) {
3088 pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
3089 logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
3090 EXPECT_TRUE(pmsgActiveAfter__android_pmsg_file_write);
3091 EXPECT_TRUE(logdwActiveAfter__android_pmsg_file_write);
3092 }
3093 #else
3094 GTEST_LOG_(INFO) << "This test does nothing.\n";
3095 #endif
3096 }
3097
3098 #ifdef __ANDROID__
__pmsg_fn(log_id_t logId,char prio,const char * filename,const char * buf,size_t len,void * arg)3099 static ssize_t __pmsg_fn(log_id_t logId, char prio, const char* filename,
3100 const char* buf, size_t len, void* arg) {
3101 EXPECT_TRUE(NULL == arg);
3102 EXPECT_EQ(LOG_ID_CRASH, logId);
3103 EXPECT_EQ(ANDROID_LOG_VERBOSE, prio);
3104 EXPECT_FALSE(NULL == strstr(__pmsg_file, filename));
3105 EXPECT_EQ(len, sizeof(max_payload_buf));
3106 EXPECT_EQ(0, strcmp(max_payload_buf, buf));
3107
3108 ++signaled;
3109 if ((len != sizeof(max_payload_buf)) || strcmp(max_payload_buf, buf)) {
3110 fprintf(stderr, "comparison fails on content \"%s\"\n", buf);
3111 }
3112 return arg || (LOG_ID_CRASH != logId) || (ANDROID_LOG_VERBOSE != prio) ||
3113 !strstr(__pmsg_file, filename) ||
3114 (len != sizeof(max_payload_buf)) ||
3115 !!strcmp(max_payload_buf, buf)
3116 ? -ENOEXEC
3117 : 1;
3118 }
3119 #endif
3120
TEST(liblog,__android_log_pmsg_file_read)3121 TEST(liblog, __android_log_pmsg_file_read) {
3122 #ifdef __ANDROID__
3123 signaled = 0;
3124
3125 __android_log_close();
3126 if (getuid() == AID_ROOT) {
3127 tested__android_log_close = true;
3128 bool pmsgActiveAfter__android_log_close = isPmsgActive();
3129 bool logdwActiveAfter__android_log_close = isLogdwActive();
3130 EXPECT_FALSE(pmsgActiveAfter__android_log_close);
3131 EXPECT_FALSE(logdwActiveAfter__android_log_close);
3132 } else if (!tested__android_log_close) {
3133 fprintf(stderr, "WARNING: can not test __android_log_close()\n");
3134 }
3135
3136 ssize_t ret = __android_log_pmsg_file_read(LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
3137 __pmsg_file, __pmsg_fn, NULL);
3138
3139 if (getuid() == AID_ROOT) {
3140 bool pmsgActiveAfter__android_log_pmsg_file_read = isPmsgActive();
3141 bool logdwActiveAfter__android_log_pmsg_file_read = isLogdwActive();
3142 EXPECT_FALSE(pmsgActiveAfter__android_log_pmsg_file_read);
3143 EXPECT_FALSE(logdwActiveAfter__android_log_pmsg_file_read);
3144 }
3145
3146 if (ret == -ENOENT) {
3147 fprintf(stderr,
3148 "No pre-boot results of liblog.__android_log_mesg_file_write to "
3149 "compare with,\n"
3150 "false positive test result.\n");
3151 return;
3152 }
3153
3154 EXPECT_LT(0, ret);
3155 EXPECT_EQ(1U, signaled);
3156 #else
3157 GTEST_LOG_(INFO) << "This test does nothing.\n";
3158 #endif
3159 }
3160 #endif // USING_LOGGER_DEFAULT
3161
3162 #ifdef USING_LOGGER_DEFAULT // Do not retest event mapping functionality
3163 #ifdef __ANDROID__
3164 // must be: '<needle:> 0 kB'
isZero(const std::string & content,std::string::size_type pos,const char * needle)3165 static bool isZero(const std::string& content, std::string::size_type pos,
3166 const char* needle) {
3167 std::string::size_type offset = content.find(needle, pos);
3168 return (offset != std::string::npos) &&
3169 ((offset = content.find_first_not_of(" \t", offset + strlen(needle))) !=
3170 std::string::npos) &&
3171 (content.find_first_not_of("0", offset) != offset);
3172 }
3173
3174 // must not be: '<needle:> 0 kB'
isNotZero(const std::string & content,std::string::size_type pos,const char * needle)3175 static bool isNotZero(const std::string& content, std::string::size_type pos,
3176 const char* needle) {
3177 std::string::size_type offset = content.find(needle, pos);
3178 return (offset != std::string::npos) &&
3179 ((offset = content.find_first_not_of(" \t", offset + strlen(needle))) !=
3180 std::string::npos) &&
3181 (content.find_first_not_of("123456789", offset) != offset);
3182 }
3183
event_log_tags_test_smap(pid_t pid)3184 static void event_log_tags_test_smap(pid_t pid) {
3185 std::string filename = android::base::StringPrintf("/proc/%d/smaps", pid);
3186
3187 std::string content;
3188 if (!android::base::ReadFileToString(filename, &content)) return;
3189
3190 bool shared_ok = false;
3191 bool private_ok = false;
3192 bool anonymous_ok = false;
3193 bool pass_ok = false;
3194
3195 static const char event_log_tags[] = "event-log-tags";
3196 std::string::size_type pos = 0;
3197 while ((pos = content.find(event_log_tags, pos)) != std::string::npos) {
3198 pos += strlen(event_log_tags);
3199
3200 // must not be: 'Shared_Clean: 0 kB'
3201 bool ok =
3202 isNotZero(content, pos, "Shared_Clean:") ||
3203 // If not /etc/event-log-tags, thus r/w, then half points
3204 // back for not 'Shared_Dirty: 0 kB'
3205 ((content.substr(pos - 5 - strlen(event_log_tags), 5) != "/etc/") &&
3206 isNotZero(content, pos, "Shared_Dirty:"));
3207 if (ok && !pass_ok) {
3208 shared_ok = true;
3209 } else if (!ok) {
3210 shared_ok = false;
3211 }
3212
3213 // must be: 'Private_Dirty: 0 kB' and 'Private_Clean: 0 kB'
3214 ok = isZero(content, pos, "Private_Dirty:") ||
3215 isZero(content, pos, "Private_Clean:");
3216 if (ok && !pass_ok) {
3217 private_ok = true;
3218 } else if (!ok) {
3219 private_ok = false;
3220 }
3221
3222 // must be: 'Anonymous: 0 kB'
3223 ok = isZero(content, pos, "Anonymous:");
3224 if (ok && !pass_ok) {
3225 anonymous_ok = true;
3226 } else if (!ok) {
3227 anonymous_ok = false;
3228 }
3229
3230 pass_ok = true;
3231 }
3232 content = "";
3233
3234 if (!pass_ok) return;
3235 if (shared_ok && anonymous_ok && private_ok) return;
3236
3237 filename = android::base::StringPrintf("/proc/%d/comm", pid);
3238 android::base::ReadFileToString(filename, &content);
3239 content = android::base::StringPrintf(
3240 "%d:%s", pid, content.substr(0, content.find("\n")).c_str());
3241
3242 EXPECT_TRUE(IsOk(shared_ok, content));
3243 EXPECT_TRUE(IsOk(private_ok, content));
3244 EXPECT_TRUE(IsOk(anonymous_ok, content));
3245 }
3246 #endif // __ANDROID__
3247
TEST(liblog,event_log_tags)3248 TEST(liblog, event_log_tags) {
3249 #ifdef __ANDROID__
3250 std::unique_ptr<DIR, int (*)(DIR*)> proc_dir(opendir("/proc"), closedir);
3251 ASSERT_FALSE(!proc_dir);
3252
3253 dirent* e;
3254 while ((e = readdir(proc_dir.get()))) {
3255 if (e->d_type != DT_DIR) continue;
3256 if (!isdigit(e->d_name[0])) continue;
3257 long long id = atoll(e->d_name);
3258 if (id <= 0) continue;
3259 pid_t pid = id;
3260 if (id != pid) continue;
3261 event_log_tags_test_smap(pid);
3262 }
3263 #else
3264 GTEST_LOG_(INFO) << "This test does nothing.\n";
3265 #endif
3266 }
3267 #endif // USING_LOGGER_DEFAULT
3268
3269 #ifdef USING_LOGGER_DEFAULT // Do not retest ratelimit
TEST(liblog,__android_log_ratelimit)3270 TEST(liblog, __android_log_ratelimit) {
3271 time_t state = 0;
3272
3273 errno = 42;
3274 // Prime
3275 __android_log_ratelimit(3, &state);
3276 EXPECT_EQ(errno, 42);
3277 // Check
3278 EXPECT_FALSE(__android_log_ratelimit(3, &state));
3279 sleep(1);
3280 EXPECT_FALSE(__android_log_ratelimit(3, &state));
3281 sleep(4);
3282 EXPECT_TRUE(__android_log_ratelimit(3, &state));
3283 sleep(5);
3284 EXPECT_TRUE(__android_log_ratelimit(3, &state));
3285
3286 // API checks
3287 IF_ALOG_RATELIMIT_LOCAL(3, &state) {
3288 EXPECT_FALSE(0 != "IF_ALOG_RATELIMIT_LOCAL(3, &state)");
3289 }
3290
3291 IF_ALOG_RATELIMIT() {
3292 ;
3293 }
3294 else {
3295 EXPECT_TRUE(0 == "IF_ALOG_RATELIMIT()");
3296 }
3297 IF_ALOG_RATELIMIT() {
3298 EXPECT_FALSE(0 != "IF_ALOG_RATELIMIT()");
3299 }
3300 // Do not test default seconds, to allow liblog to tune freely
3301 }
3302 #endif // USING_LOGGER_DEFAULT
3303
3304 #ifdef USING_LOGGER_DEFAULT // Do not retest event mapping functionality
TEST(liblog,android_lookupEventTagNum)3305 TEST(liblog, android_lookupEventTagNum) {
3306 #ifdef __ANDROID__
3307 EventTagMap* map = android_openEventTagMap(NULL);
3308 EXPECT_TRUE(NULL != map);
3309 std::string Name = android::base::StringPrintf("a%d", getpid());
3310 int tag = android_lookupEventTagNum(map, Name.c_str(), "(new|1)",
3311 ANDROID_LOG_UNKNOWN);
3312 android_closeEventTagMap(map);
3313 if (tag == -1) system("tail -3 /dev/event-log-tags >&2");
3314 EXPECT_NE(-1, tag);
3315 EXPECT_NE(0, tag);
3316 EXPECT_GT(UINT32_MAX, (unsigned)tag);
3317 #else
3318 GTEST_LOG_(INFO) << "This test does nothing.\n";
3319 #endif
3320 }
3321 #endif // USING_LOGGER_DEFAULT
3322