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