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