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