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((int)((line_overhead * num_lines) + size),
390 android_log_printLogLine(logformat, fileno(stderr), &entry));
391 } else {
392 EXPECT_EQ((int)((line_overhead * num_lines) + size),
393 android_log_printLogLine(logformat, fileno(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((int)(((line_overhead + sizeof(tag)) * num_lines) + size),
472 android_log_printLogLine(logformat, fileno(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
693 memset(¶m, 0, sizeof(param));
694 pthread_attr_setschedparam(&attr, ¶m);
695 pthread_attr_setschedpolicy(&attr, SCHED_BATCH);
696
697 if (pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED)) {
698 pthread_attr_destroy(&attr);
699 return -1;
700 }
701
702 pthread_t thread;
703 if (pthread_create(&thread, &attr, running_thread, NULL)) {
704 pthread_attr_destroy(&attr);
705 return -1;
706 }
707
708 pthread_attr_destroy(&attr);
709 return 0;
710 }
711 #endif
712
TEST(liblog,android_logger_list_read__cpu_thread)713 TEST(liblog, android_logger_list_read__cpu_thread) {
714 #ifdef __ANDROID__
715 struct logger_list* logger_list;
716 unsigned long long v = 0xDEADBEAFA55A0000ULL;
717
718 pid_t pid = getpid();
719
720 v += pid & 0xFFFF;
721
722 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(LOG_ID_EVENTS, 0, 1000, pid)));
723
724 int count = 0;
725
726 int signals = 0;
727
728 unsigned long long uticks_start;
729 unsigned long long sticks_start;
730 get_ticks(&uticks_start, &sticks_start);
731
732 const unsigned alarm_time = 10;
733
734 memset(&signal_time, 0, sizeof(signal_time));
735
736 signaled = 0;
737 EXPECT_EQ(0, start_thread());
738
739 signal(SIGALRM, caught_blocking_thread);
740 alarm(alarm_time);
741
742 do {
743 log_msg log_msg;
744 if (LOG_FAILURE_RETRY(android_logger_list_read(logger_list, &log_msg)) <= 0) {
745 break;
746 }
747
748 alarm(alarm_time);
749
750 ++count;
751
752 ASSERT_EQ(log_msg.entry.pid, pid);
753
754 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
755 (log_msg.id() != LOG_ID_EVENTS)) {
756 continue;
757 }
758
759 android_log_event_long_t* eventData;
760 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
761
762 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
763 continue;
764 }
765
766 char* cp = reinterpret_cast<char*>(&eventData->payload.data);
767 unsigned long long l = cp[0] & 0xFF;
768 l |= (unsigned long long)(cp[1] & 0xFF) << 8;
769 l |= (unsigned long long)(cp[2] & 0xFF) << 16;
770 l |= (unsigned long long)(cp[3] & 0xFF) << 24;
771 l |= (unsigned long long)(cp[4] & 0xFF) << 32;
772 l |= (unsigned long long)(cp[5] & 0xFF) << 40;
773 l |= (unsigned long long)(cp[6] & 0xFF) << 48;
774 l |= (unsigned long long)(cp[7] & 0xFF) << 56;
775
776 if (l == v) {
777 ++signals;
778 break;
779 }
780 } while (!signaled || (log_time(CLOCK_MONOTONIC) < signal_time));
781 alarm(0);
782 signal(SIGALRM, SIG_DFL);
783
784 EXPECT_LE(1, count);
785
786 EXPECT_EQ(1, signals);
787
788 android_logger_list_close(logger_list);
789
790 unsigned long long uticks_end;
791 unsigned long long sticks_end;
792 get_ticks(&uticks_end, &sticks_end);
793
794 // Less than 1% in either user or system time, or both
795 const unsigned long long one_percent_ticks = alarm_time;
796 unsigned long long user_ticks = uticks_end - uticks_start;
797 unsigned long long system_ticks = sticks_end - sticks_start;
798 EXPECT_GT(one_percent_ticks, user_ticks);
799 EXPECT_GT(one_percent_ticks, system_ticks);
800 EXPECT_GT(one_percent_ticks, user_ticks + system_ticks);
801 #else
802 GTEST_LOG_(INFO) << "This test does nothing.\n";
803 #endif
804 }
805 #endif // ENABLE_FLAKY_TESTS
806
807 static const char max_payload_buf[] =
808 "LEONATO\n\
809 I learn in this letter that Don Peter of Arragon\n\
810 comes this night to Messina\n\
811 MESSENGER\n\
812 He is very near by this: he was not three leagues off\n\
813 when I left him\n\
814 LEONATO\n\
815 How many gentlemen have you lost in this action?\n\
816 MESSENGER\n\
817 But few of any sort, and none of name\n\
818 LEONATO\n\
819 A victory is twice itself when the achiever brings\n\
820 home full numbers. I find here that Don Peter hath\n\
821 bestowed much honour on a young Florentine called Claudio\n\
822 MESSENGER\n\
823 Much deserved on his part and equally remembered by\n\
824 Don Pedro: he hath borne himself beyond the\n\
825 promise of his age, doing, in the figure of a lamb,\n\
826 the feats of a lion: he hath indeed better\n\
827 bettered expectation than you must expect of me to\n\
828 tell you how\n\
829 LEONATO\n\
830 He hath an uncle here in Messina will be very much\n\
831 glad of it.\n\
832 MESSENGER\n\
833 I have already delivered him letters, and there\n\
834 appears much joy in him; even so much that joy could\n\
835 not show itself modest enough without a badge of\n\
836 bitterness.\n\
837 LEONATO\n\
838 Did he break out into tears?\n\
839 MESSENGER\n\
840 In great measure.\n\
841 LEONATO\n\
842 A kind overflow of kindness: there are no faces\n\
843 truer than those that are so washed. How much\n\
844 better is it to weep at joy than to joy at weeping!\n\
845 BEATRICE\n\
846 I pray you, is Signior Mountanto returned from the\n\
847 wars or no?\n\
848 MESSENGER\n\
849 I know none of that name, lady: there was none such\n\
850 in the army of any sort.\n\
851 LEONATO\n\
852 What is he that you ask for, niece?\n\
853 HERO\n\
854 My cousin means Signior Benedick of Padua.\n\
855 MESSENGER\n\
856 O, he's returned; and as pleasant as ever he was.\n\
857 BEATRICE\n\
858 He set up his bills here in Messina and challenged\n\
859 Cupid at the flight; and my uncle's fool, reading\n\
860 the challenge, subscribed for Cupid, and challenged\n\
861 him at the bird-bolt. I pray you, how many hath he\n\
862 killed and eaten in these wars? But how many hath\n\
863 he killed? for indeed I promised to eat all of his killing.\n\
864 LEONATO\n\
865 Faith, niece, you tax Signior Benedick too much;\n\
866 but he'll be meet with you, I doubt it not.\n\
867 MESSENGER\n\
868 He hath done good service, lady, in these wars.\n\
869 BEATRICE\n\
870 You had musty victual, and he hath holp to eat it:\n\
871 he is a very valiant trencherman; he hath an\n\
872 excellent stomach.\n\
873 MESSENGER\n\
874 And a good soldier too, lady.\n\
875 BEATRICE\n\
876 And a good soldier to a lady: but what is he to a lord?\n\
877 MESSENGER\n\
878 A lord to a lord, a man to a man; stuffed with all\n\
879 honourable virtues.\n\
880 BEATRICE\n\
881 It is so, indeed; he is no less than a stuffed man:\n\
882 but for the stuffing,--well, we are all mortal.\n\
883 LEONATO\n\
884 You must not, sir, mistake my niece. There is a\n\
885 kind of merry war betwixt Signior Benedick and her:\n\
886 they never meet but there's a skirmish of wit\n\
887 between them.\n\
888 BEATRICE\n\
889 Alas! he gets nothing by that. In our last\n\
890 conflict four of his five wits went halting off, and\n\
891 now is the whole man governed with one: so that if\n\
892 he have wit enough to keep himself warm, let him\n\
893 bear it for a difference between himself and his\n\
894 horse; for it is all the wealth that he hath left,\n\
895 to be known a reasonable creature. Who is his\n\
896 companion now? He hath every month a new sworn brother.\n\
897 MESSENGER\n\
898 Is't possible?\n\
899 BEATRICE\n\
900 Very easily possible: he wears his faith but as\n\
901 the fashion of his hat; it ever changes with the\n\
902 next block.\n\
903 MESSENGER\n\
904 I see, lady, the gentleman is not in your books.\n\
905 BEATRICE\n\
906 No; an he were, I would burn my study. But, I pray\n\
907 you, who is his companion? Is there no young\n\
908 squarer now that will make a voyage with him to the devil?\n\
909 MESSENGER\n\
910 He is most in the company of the right noble Claudio.\n\
911 BEATRICE\n\
912 O Lord, he will hang upon him like a disease: he\n\
913 is sooner caught than the pestilence, and the taker\n\
914 runs presently mad. God help the noble Claudio! if\n\
915 he have caught the Benedick, it will cost him a\n\
916 thousand pound ere a' be cured.\n\
917 MESSENGER\n\
918 I will hold friends with you, lady.\n\
919 BEATRICE\n\
920 Do, good friend.\n\
921 LEONATO\n\
922 You will never run mad, niece.\n\
923 BEATRICE\n\
924 No, not till a hot January.\n\
925 MESSENGER\n\
926 Don Pedro is approached.\n\
927 Enter DON PEDRO, DON JOHN, CLAUDIO, BENEDICK, and BALTHASAR\n\
928 \n\
929 DON PEDRO\n\
930 Good Signior Leonato, you are come to meet your\n\
931 trouble: the fashion of the world is to avoid\n\
932 cost, and you encounter it\n\
933 LEONATO\n\
934 Never came trouble to my house in the likeness of your grace,\n\
935 for trouble being gone, comfort should remain, but\n\
936 when you depart from me, sorrow abides and happiness\n\
937 takes his leave.";
938
TEST(liblog,max_payload)939 TEST(liblog, max_payload) {
940 #ifdef __ANDROID__
941 static const char max_payload_tag[] = "TEST_max_payload_and_longish_tag_XXXX";
942 #define SIZEOF_MAX_PAYLOAD_BUF (LOGGER_ENTRY_MAX_PAYLOAD - sizeof(max_payload_tag) - 1)
943
944 pid_t pid = getpid();
945 char tag[sizeof(max_payload_tag)];
946 memcpy(tag, max_payload_tag, sizeof(tag));
947 snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
948
949 auto write_function = [&] {
950 LOG_FAILURE_RETRY(
951 __android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, tag, max_payload_buf));
952 };
953
954 ssize_t max_len = 0;
955 auto check_function = [&](log_msg log_msg, bool* found) {
956 char* data = log_msg.msg();
957
958 if (!data || strcmp(++data, tag)) {
959 return;
960 }
961
962 data += strlen(data) + 1;
963
964 const char* left = data;
965 const char* right = max_payload_buf;
966 while (*left && *right && (*left == *right)) {
967 ++left;
968 ++right;
969 }
970
971 if (max_len <= (left - data)) {
972 max_len = left - data + 1;
973 }
974
975 if (max_len > 512) {
976 *found = true;
977 }
978 };
979
980 RunLogTests(LOG_ID_SYSTEM, write_function, check_function);
981
982 EXPECT_LE(SIZEOF_MAX_PAYLOAD_BUF, static_cast<size_t>(max_len));
983 #else
984 GTEST_LOG_(INFO) << "This test does nothing.\n";
985 #endif
986 }
987
TEST(liblog,__android_log_buf_print__maxtag)988 TEST(liblog, __android_log_buf_print__maxtag) {
989 #ifdef __ANDROID__
990 auto write_function = [&] {
991 EXPECT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, max_payload_buf,
992 max_payload_buf));
993 };
994
995 auto check_function = [&](log_msg log_msg, bool* found) {
996 if ((size_t)log_msg.entry.len < LOGGER_ENTRY_MAX_PAYLOAD) {
997 return;
998 }
999
1000 *found = true;
1001
1002 AndroidLogFormat* logformat = android_log_format_new();
1003 EXPECT_TRUE(NULL != logformat);
1004 AndroidLogEntry entry;
1005 int processLogBuffer = android_log_processLogBuffer(&log_msg.entry, &entry);
1006 EXPECT_EQ(0, processLogBuffer);
1007 if (processLogBuffer == 0) {
1008 fflush(stderr);
1009 int printLogLine =
1010 android_log_printLogLine(logformat, fileno(stderr), &entry);
1011 // Legacy tag truncation
1012 EXPECT_LE(128, printLogLine);
1013 // Measured maximum if we try to print part of the tag as message
1014 EXPECT_GT(LOGGER_ENTRY_MAX_PAYLOAD * 13 / 8, printLogLine);
1015 }
1016 android_log_format_free(logformat);
1017 };
1018
1019 RunLogTests(LOG_ID_MAIN, write_function, check_function);
1020
1021 #else
1022 GTEST_LOG_(INFO) << "This test does nothing.\n";
1023 #endif
1024 }
1025
1026 // Note: This test is tautological. android_logger_list_read() calls recv() with
1027 // LOGGER_ENTRY_MAX_PAYLOAD as its size argument, so it's not possible for this test to read a
1028 // payload larger than that size.
TEST(liblog,too_big_payload)1029 TEST(liblog, too_big_payload) {
1030 #ifdef __ANDROID__
1031 pid_t pid = getpid();
1032 static const char big_payload_tag[] = "TEST_big_payload_XXXX";
1033 char tag[sizeof(big_payload_tag)];
1034 memcpy(tag, big_payload_tag, sizeof(tag));
1035 snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
1036
1037 std::string longString(3266519, 'x');
1038 ssize_t ret;
1039
1040 auto write_function = [&] {
1041 ret = LOG_FAILURE_RETRY(
1042 __android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, tag, longString.c_str()));
1043 };
1044
1045 auto check_function = [&](log_msg log_msg, bool* found) {
1046 char* data = log_msg.msg();
1047
1048 if (!data || strcmp(++data, tag)) {
1049 return;
1050 }
1051
1052 data += strlen(data) + 1;
1053
1054 const char* left = data;
1055 const char* right = longString.c_str();
1056 while (*left && *right && (*left == *right)) {
1057 ++left;
1058 ++right;
1059 }
1060
1061 ssize_t len = left - data + 1;
1062 // Check that we don't see any entries larger than the max payload.
1063 EXPECT_LE(static_cast<size_t>(len), LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag));
1064
1065 // Once we've found our expected entry, break.
1066 if (len == LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag)) {
1067 *found = true;
1068 }
1069 };
1070
1071 RunLogTests(LOG_ID_SYSTEM, write_function, check_function);
1072
1073 #else
1074 GTEST_LOG_(INFO) << "This test does nothing.\n";
1075 #endif
1076 }
1077
TEST(liblog,dual_reader)1078 TEST(liblog, dual_reader) {
1079 #ifdef __ANDROID__
1080 static const int expected_count1 = 25;
1081 static const int expected_count2 = 25;
1082
1083 pid_t pid = getpid();
1084
1085 auto logger_list1 = std::unique_ptr<struct logger_list, ListCloser>{
1086 android_logger_list_open(LOG_ID_MAIN, 0, expected_count1, pid)};
1087 ASSERT_TRUE(logger_list1);
1088
1089 auto logger_list2 = std::unique_ptr<struct logger_list, ListCloser>{
1090 android_logger_list_open(LOG_ID_MAIN, 0, expected_count2, pid)};
1091 ASSERT_TRUE(logger_list2);
1092
1093 for (int i = 25; i > 0; --i) {
1094 static const char fmt[] = "dual_reader %02d";
1095 char buffer[sizeof(fmt) + 8];
1096 snprintf(buffer, sizeof(buffer), fmt, i);
1097 LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO,
1098 "liblog", buffer));
1099 }
1100
1101 alarm(2);
1102 auto alarm_guard = android::base::make_scope_guard([] { alarm(0); });
1103
1104 // Wait until we see all messages with the blocking reader.
1105 int count1 = 0;
1106 int count2 = 0;
1107
1108 while (count1 != expected_count2 || count2 != expected_count2) {
1109 log_msg log_msg;
1110 if (count1 < expected_count1) {
1111 ASSERT_GT(android_logger_list_read(logger_list1.get(), &log_msg), 0);
1112 count1++;
1113 }
1114 if (count2 < expected_count2) {
1115 ASSERT_GT(android_logger_list_read(logger_list2.get(), &log_msg), 0);
1116 count2++;
1117 }
1118 }
1119
1120 // Test again with the nonblocking reader.
1121 auto logger_list_non_block1 = std::unique_ptr<struct logger_list, ListCloser>{
1122 android_logger_list_open(LOG_ID_MAIN, ANDROID_LOG_NONBLOCK, expected_count1, pid)};
1123 ASSERT_TRUE(logger_list_non_block1);
1124
1125 auto logger_list_non_block2 = std::unique_ptr<struct logger_list, ListCloser>{
1126 android_logger_list_open(LOG_ID_MAIN, ANDROID_LOG_NONBLOCK, expected_count2, pid)};
1127 ASSERT_TRUE(logger_list_non_block2);
1128 count1 = 0;
1129 count2 = 0;
1130 bool done1 = false;
1131 bool done2 = false;
1132
1133 while (!done1 || !done2) {
1134 log_msg log_msg;
1135
1136 if (!done1) {
1137 if (android_logger_list_read(logger_list_non_block1.get(), &log_msg) <= 0) {
1138 done1 = true;
1139 } else {
1140 ++count1;
1141 }
1142 }
1143
1144 if (!done2) {
1145 if (android_logger_list_read(logger_list_non_block2.get(), &log_msg) <= 0) {
1146 done2 = true;
1147 } else {
1148 ++count2;
1149 }
1150 }
1151 }
1152
1153 EXPECT_EQ(expected_count1, count1);
1154 EXPECT_EQ(expected_count2, count2);
1155 #else
1156 GTEST_LOG_(INFO) << "This test does nothing.\n";
1157 #endif
1158 }
1159
checkPriForTag(AndroidLogFormat * p_format,const char * tag,android_LogPriority pri)1160 static bool checkPriForTag(AndroidLogFormat* p_format, const char* tag,
1161 android_LogPriority pri) {
1162 return android_log_shouldPrintLine(p_format, tag, pri) &&
1163 !android_log_shouldPrintLine(p_format, tag,
1164 (android_LogPriority)(pri - 1));
1165 }
1166
TEST(liblog,filterRule)1167 TEST(liblog, filterRule) {
1168 static const char tag[] = "random";
1169
1170 AndroidLogFormat* p_format = android_log_format_new();
1171
1172 android_log_addFilterRule(p_format, "*:i");
1173
1174 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_INFO));
1175 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1176 0);
1177 android_log_addFilterRule(p_format, "*");
1178 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1179 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1180 android_log_addFilterRule(p_format, "*:v");
1181 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_VERBOSE));
1182 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1183 android_log_addFilterRule(p_format, "*:i");
1184 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_INFO));
1185 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1186 0);
1187
1188 android_log_addFilterRule(p_format, tag);
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:v");
1192 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_VERBOSE));
1193 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1194 android_log_addFilterRule(p_format, "random:d");
1195 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1196 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) > 0);
1197 android_log_addFilterRule(p_format, "random:w");
1198 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1199 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1200 0);
1201
1202 android_log_addFilterRule(p_format, "crap:*");
1203 EXPECT_TRUE(checkPriForTag(p_format, "crap", ANDROID_LOG_VERBOSE));
1204 EXPECT_TRUE(
1205 android_log_shouldPrintLine(p_format, "crap", ANDROID_LOG_VERBOSE) > 0);
1206
1207 // invalid expression
1208 EXPECT_TRUE(android_log_addFilterRule(p_format, "random:z") < 0);
1209 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1210 EXPECT_TRUE(android_log_shouldPrintLine(p_format, tag, ANDROID_LOG_DEBUG) ==
1211 0);
1212
1213 // Issue #550946
1214 EXPECT_TRUE(android_log_addFilterString(p_format, " ") == 0);
1215 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_WARN));
1216
1217 // note trailing space
1218 EXPECT_TRUE(android_log_addFilterString(p_format, "*:s random:d ") == 0);
1219 EXPECT_TRUE(checkPriForTag(p_format, tag, ANDROID_LOG_DEBUG));
1220
1221 EXPECT_TRUE(android_log_addFilterString(p_format, "*:s random:z") < 0);
1222
1223 #if 0 // bitrot, seek update
1224 char defaultBuffer[512];
1225
1226 android_log_formatLogLine(p_format,
1227 defaultBuffer, sizeof(defaultBuffer), 0, ANDROID_LOG_ERROR, 123,
1228 123, 123, tag, "nofile", strlen("Hello"), "Hello", NULL);
1229
1230 fprintf(stderr, "%s\n", defaultBuffer);
1231 #endif
1232
1233 android_log_format_free(p_format);
1234 }
1235
1236 #ifdef ENABLE_FLAKY_TESTS
TEST(liblog,is_loggable)1237 TEST(liblog, is_loggable) {
1238 #ifdef __ANDROID__
1239 static const char tag[] = "is_loggable";
1240 static const char log_namespace[] = "persist.log.tag.";
1241 static const size_t base_offset = 8; /* skip "persist." */
1242 // sizeof("string") = strlen("string") + 1
1243 char key[sizeof(log_namespace) + sizeof(tag) - 1];
1244 char hold[4][PROP_VALUE_MAX];
1245 static const struct {
1246 int level;
1247 char type;
1248 } levels[] = {
1249 {ANDROID_LOG_VERBOSE, 'v'}, {ANDROID_LOG_DEBUG, 'd'},
1250 {ANDROID_LOG_INFO, 'i'}, {ANDROID_LOG_WARN, 'w'},
1251 {ANDROID_LOG_ERROR, 'e'}, {ANDROID_LOG_FATAL, 'a'},
1252 {ANDROID_LOG_SILENT, 's'}, {-2, 'g'}, // Illegal value, resort to default
1253 };
1254
1255 // Set up initial test condition
1256 memset(hold, 0, sizeof(hold));
1257 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1258 property_get(key, hold[0], "");
1259 property_set(key, "");
1260 property_get(key + base_offset, hold[1], "");
1261 property_set(key + base_offset, "");
1262 strcpy(key, log_namespace);
1263 key[sizeof(log_namespace) - 2] = '\0';
1264 property_get(key, hold[2], "");
1265 property_set(key, "");
1266 property_get(key, hold[3], "");
1267 property_set(key + base_offset, "");
1268
1269 // All combinations of level and defaults
1270 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1271 if (levels[i].level == -2) {
1272 continue;
1273 }
1274 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1275 if (levels[j].level == -2) {
1276 continue;
1277 }
1278 fprintf(stderr, "i=%zu j=%zu\r", i, j);
1279 bool android_log_is_loggable = __android_log_is_loggable_len(
1280 levels[i].level, tag, strlen(tag), levels[j].level);
1281 if ((levels[i].level < levels[j].level) || (levels[j].level == -1)) {
1282 if (android_log_is_loggable) {
1283 fprintf(stderr, "\n");
1284 }
1285 EXPECT_FALSE(android_log_is_loggable);
1286 for (size_t k = 10; k; --k) {
1287 EXPECT_FALSE(__android_log_is_loggable_len(
1288 levels[i].level, tag, strlen(tag), levels[j].level));
1289 }
1290 } else {
1291 if (!android_log_is_loggable) {
1292 fprintf(stderr, "\n");
1293 }
1294 EXPECT_TRUE(android_log_is_loggable);
1295 for (size_t k = 10; k; --k) {
1296 EXPECT_TRUE(__android_log_is_loggable_len(
1297 levels[i].level, tag, strlen(tag), levels[j].level));
1298 }
1299 }
1300 }
1301 }
1302
1303 // All combinations of level and tag and global properties
1304 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1305 if (levels[i].level == -2) {
1306 continue;
1307 }
1308 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1309 char buf[2];
1310 buf[0] = levels[j].type;
1311 buf[1] = '\0';
1312
1313 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1314 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1315 buf);
1316 usleep(20000);
1317 property_set(key, buf);
1318 bool android_log_is_loggable = __android_log_is_loggable_len(
1319 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1320 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1321 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1322 if (android_log_is_loggable) {
1323 fprintf(stderr, "\n");
1324 }
1325 EXPECT_FALSE(android_log_is_loggable);
1326 for (size_t k = 10; k; --k) {
1327 EXPECT_FALSE(__android_log_is_loggable_len(
1328 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1329 }
1330 } else {
1331 if (!android_log_is_loggable) {
1332 fprintf(stderr, "\n");
1333 }
1334 EXPECT_TRUE(android_log_is_loggable);
1335 for (size_t k = 10; k; --k) {
1336 EXPECT_TRUE(__android_log_is_loggable_len(
1337 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1338 }
1339 }
1340 usleep(20000);
1341 property_set(key, "");
1342
1343 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1344 key + base_offset, buf);
1345 property_set(key + base_offset, buf);
1346 android_log_is_loggable = __android_log_is_loggable_len(
1347 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1348 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1349 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1350 if (android_log_is_loggable) {
1351 fprintf(stderr, "\n");
1352 }
1353 EXPECT_FALSE(android_log_is_loggable);
1354 for (size_t k = 10; k; --k) {
1355 EXPECT_FALSE(__android_log_is_loggable_len(
1356 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1357 }
1358 } else {
1359 if (!android_log_is_loggable) {
1360 fprintf(stderr, "\n");
1361 }
1362 EXPECT_TRUE(android_log_is_loggable);
1363 for (size_t k = 10; k; --k) {
1364 EXPECT_TRUE(__android_log_is_loggable_len(
1365 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1366 }
1367 }
1368 usleep(20000);
1369 property_set(key + base_offset, "");
1370
1371 strcpy(key, log_namespace);
1372 key[sizeof(log_namespace) - 2] = '\0';
1373 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1374 buf);
1375 property_set(key, buf);
1376 android_log_is_loggable = __android_log_is_loggable_len(
1377 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1378 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1379 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1380 if (android_log_is_loggable) {
1381 fprintf(stderr, "\n");
1382 }
1383 EXPECT_FALSE(android_log_is_loggable);
1384 for (size_t k = 10; k; --k) {
1385 EXPECT_FALSE(__android_log_is_loggable_len(
1386 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1387 }
1388 } else {
1389 if (!android_log_is_loggable) {
1390 fprintf(stderr, "\n");
1391 }
1392 EXPECT_TRUE(android_log_is_loggable);
1393 for (size_t k = 10; k; --k) {
1394 EXPECT_TRUE(__android_log_is_loggable_len(
1395 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1396 }
1397 }
1398 usleep(20000);
1399 property_set(key, "");
1400
1401 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1402 key + base_offset, buf);
1403 property_set(key + base_offset, buf);
1404 android_log_is_loggable = __android_log_is_loggable_len(
1405 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1406 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1407 ((levels[i].level < ANDROID_LOG_DEBUG) && (levels[j].level == -2))) {
1408 if (android_log_is_loggable) {
1409 fprintf(stderr, "\n");
1410 }
1411 EXPECT_FALSE(android_log_is_loggable);
1412 for (size_t k = 10; k; --k) {
1413 EXPECT_FALSE(__android_log_is_loggable_len(
1414 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1415 }
1416 } else {
1417 if (!android_log_is_loggable) {
1418 fprintf(stderr, "\n");
1419 }
1420 EXPECT_TRUE(android_log_is_loggable);
1421 for (size_t k = 10; k; --k) {
1422 EXPECT_TRUE(__android_log_is_loggable_len(
1423 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1424 }
1425 }
1426 usleep(20000);
1427 property_set(key + base_offset, "");
1428 }
1429 }
1430
1431 // All combinations of level and tag properties, but with global set to INFO
1432 strcpy(key, log_namespace);
1433 key[sizeof(log_namespace) - 2] = '\0';
1434 usleep(20000);
1435 property_set(key, "I");
1436 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1437 for (size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
1438 if (levels[i].level == -2) {
1439 continue;
1440 }
1441 for (size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
1442 char buf[2];
1443 buf[0] = levels[j].type;
1444 buf[1] = '\0';
1445
1446 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j, key,
1447 buf);
1448 usleep(20000);
1449 property_set(key, buf);
1450 bool android_log_is_loggable = __android_log_is_loggable_len(
1451 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1452 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1453 ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
1454 && (levels[j].level == -2))) {
1455 if (android_log_is_loggable) {
1456 fprintf(stderr, "\n");
1457 }
1458 EXPECT_FALSE(android_log_is_loggable);
1459 for (size_t k = 10; k; --k) {
1460 EXPECT_FALSE(__android_log_is_loggable_len(
1461 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1462 }
1463 } else {
1464 if (!android_log_is_loggable) {
1465 fprintf(stderr, "\n");
1466 }
1467 EXPECT_TRUE(android_log_is_loggable);
1468 for (size_t k = 10; k; --k) {
1469 EXPECT_TRUE(__android_log_is_loggable_len(
1470 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1471 }
1472 }
1473 usleep(20000);
1474 property_set(key, "");
1475
1476 fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r", i, j,
1477 key + base_offset, buf);
1478 property_set(key + base_offset, buf);
1479 android_log_is_loggable = __android_log_is_loggable_len(
1480 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG);
1481 if ((levels[i].level < levels[j].level) || (levels[j].level == -1) ||
1482 ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
1483 && (levels[j].level == -2))) {
1484 if (android_log_is_loggable) {
1485 fprintf(stderr, "\n");
1486 }
1487 EXPECT_FALSE(android_log_is_loggable);
1488 for (size_t k = 10; k; --k) {
1489 EXPECT_FALSE(__android_log_is_loggable_len(
1490 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1491 }
1492 } else {
1493 if (!android_log_is_loggable) {
1494 fprintf(stderr, "\n");
1495 }
1496 EXPECT_TRUE(android_log_is_loggable);
1497 for (size_t k = 10; k; --k) {
1498 EXPECT_TRUE(__android_log_is_loggable_len(
1499 levels[i].level, tag, strlen(tag), ANDROID_LOG_DEBUG));
1500 }
1501 }
1502 usleep(20000);
1503 property_set(key + base_offset, "");
1504 }
1505 }
1506
1507 // reset parms
1508 snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
1509 usleep(20000);
1510 property_set(key, hold[0]);
1511 property_set(key + base_offset, hold[1]);
1512 strcpy(key, log_namespace);
1513 key[sizeof(log_namespace) - 2] = '\0';
1514 property_set(key, hold[2]);
1515 property_set(key + base_offset, hold[3]);
1516 #else
1517 GTEST_LOG_(INFO) << "This test does nothing.\n";
1518 #endif
1519 }
1520 #endif // ENABLE_FLAKY_TESTS
1521
1522 #ifdef ENABLE_FLAKY_TESTS
1523 // Following tests the specific issues surrounding error handling wrt logd.
1524 // Kills logd and toss all collected data, equivalent to logcat -b all -c,
1525 // except we also return errors to the logging callers.
1526 #ifdef __ANDROID__
1527 // helper to liblog.enoent to count end-to-end matching logging messages.
count_matching_ts(log_time ts)1528 static int count_matching_ts(log_time ts) {
1529 usleep(1000000);
1530
1531 pid_t pid = getpid();
1532
1533 struct logger_list* logger_list =
1534 android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_NONBLOCK, 1000, pid);
1535
1536 int count = 0;
1537 if (logger_list == NULL) return count;
1538
1539 for (;;) {
1540 log_msg log_msg;
1541 if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
1542
1543 if (log_msg.entry.len != sizeof(android_log_event_long_t)) continue;
1544 if (log_msg.id() != LOG_ID_EVENTS) continue;
1545
1546 android_log_event_long_t* eventData;
1547 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
1548 if (!eventData) continue;
1549 if (eventData->payload.type != EVENT_TYPE_LONG) continue;
1550
1551 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
1552 if (ts != tx) continue;
1553
1554 // found event message with matching timestamp signature in payload
1555 ++count;
1556 }
1557 android_logger_list_close(logger_list);
1558
1559 return count;
1560 }
1561
TEST(liblog,enoent)1562 TEST(liblog, enoent) {
1563 #ifdef __ANDROID__
1564 if (getuid() != 0) {
1565 GTEST_SKIP() << "Skipping test, must be run as root.";
1566 return;
1567 }
1568
1569 log_time ts(CLOCK_MONOTONIC);
1570 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
1571 EXPECT_EQ(1, count_matching_ts(ts));
1572
1573 // This call will fail unless we are root, beware of any
1574 // test prior to this one playing with setuid and causing interference.
1575 // We need to run before these tests so that they do not interfere with
1576 // this test.
1577 //
1578 // Stopping the logger can affect some other test's expectations as they
1579 // count on the log buffers filled with existing content, and this
1580 // effectively does a logcat -c emptying it. So we want this test to be
1581 // as near as possible to the bottom of the file. For example
1582 // liblog.android_logger_get_ is one of those tests that has no recourse
1583 // and that would be adversely affected by emptying the log if it was run
1584 // right after this test.
1585 system("stop logd");
1586 usleep(1000000);
1587
1588 // A clean stop like we are testing returns -ENOENT, but in the _real_
1589 // world we could get -ENOTCONN or -ECONNREFUSED depending on timing.
1590 // Alas we can not test these other return values; accept that they
1591 // are treated equally within the open-retry logic in liblog.
1592 ts = log_time(CLOCK_MONOTONIC);
1593 int ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
1594 std::string content = android::base::StringPrintf(
1595 "__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
1596 ret, (ret <= 0) ? strerror(-ret) : "(content sent)");
1597 EXPECT_TRUE(ret == -ENOENT || ret == -ENOTCONN || ret == -ECONNREFUSED) << content;
1598 ret = __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts));
1599 content = android::base::StringPrintf(
1600 "__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) = %d %s\n",
1601 ret, (ret <= 0) ? strerror(-ret) : "(content sent)");
1602 EXPECT_TRUE(ret == -ENOENT || ret == -ENOTCONN || ret == -ECONNREFUSED) << content;
1603 EXPECT_EQ(0, count_matching_ts(ts));
1604
1605 system("start logd");
1606 usleep(1000000);
1607
1608 EXPECT_EQ(0, count_matching_ts(ts));
1609
1610 ts = log_time(CLOCK_MONOTONIC);
1611 EXPECT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
1612 EXPECT_EQ(1, count_matching_ts(ts));
1613
1614 #else
1615 GTEST_LOG_(INFO) << "This test does nothing.\n";
1616 #endif
1617 }
1618 #endif // __ANDROID__
1619 #endif // ENABLE_FLAKY_TESTS
1620
1621 // Below this point we run risks of setuid(AID_SYSTEM) which may affect others.
1622
1623 #ifdef ENABLE_FLAKY_TESTS
1624 // Do not retest properties, and cannot log into LOG_ID_SECURITY
TEST(liblog,__security)1625 TEST(liblog, __security) {
1626 #ifdef __ANDROID__
1627 static const char persist_key[] = "persist.logd.security";
1628 static const char readonly_key[] = "ro.organization_owned";
1629 // A silly default value that can never be in readonly_key so
1630 // that it can be determined the property is not set.
1631 static const char nothing_val[] = "_NOTHING_TO_SEE_HERE_";
1632 char persist[PROP_VALUE_MAX];
1633 char persist_hold[PROP_VALUE_MAX];
1634 char readonly[PROP_VALUE_MAX];
1635
1636 // First part of this test requires the test itself to have the appropriate
1637 // permissions. If we do not have them, we can not override them, so we
1638 // bail rather than give a failing grade.
1639 property_get(persist_key, persist, "");
1640 fprintf(stderr, "INFO: getprop %s -> %s\n", persist_key, persist);
1641 strncpy(persist_hold, persist, PROP_VALUE_MAX);
1642 property_get(readonly_key, readonly, nothing_val);
1643 fprintf(stderr, "INFO: getprop %s -> %s\n", readonly_key, readonly);
1644
1645 if (!strcmp(readonly, nothing_val)) {
1646 // Lets check if we can set the value (we should not be allowed to do so)
1647 EXPECT_FALSE(__android_log_security());
1648 fprintf(stderr, "WARNING: setting ro.organization_owned to a domain\n");
1649 static const char domain[] = "com.google.android.SecOps.DeviceOwner";
1650 EXPECT_NE(0, property_set(readonly_key, domain));
1651 useconds_t total_time = 0;
1652 static const useconds_t seconds = 1000000;
1653 static const useconds_t max_time = 5 * seconds; // not going to happen
1654 static const useconds_t rest = 20 * 1000;
1655 for (; total_time < max_time; total_time += rest) {
1656 usleep(rest); // property system does not guarantee performance.
1657 property_get(readonly_key, readonly, nothing_val);
1658 if (!strcmp(readonly, domain)) {
1659 if (total_time > rest) {
1660 fprintf(stderr, "INFO: took %u.%06u seconds to set property\n",
1661 (unsigned)(total_time / seconds),
1662 (unsigned)(total_time % seconds));
1663 }
1664 break;
1665 }
1666 }
1667 EXPECT_STRNE(domain, readonly);
1668 }
1669
1670 if (!strcasecmp(readonly, "false") || !readonly[0] ||
1671 !strcmp(readonly, nothing_val)) {
1672 // not enough permissions to run tests surrounding persist.logd.security
1673 EXPECT_FALSE(__android_log_security());
1674 return;
1675 }
1676
1677 if (!strcasecmp(persist, "true")) {
1678 EXPECT_TRUE(__android_log_security());
1679 } else {
1680 EXPECT_FALSE(__android_log_security());
1681 }
1682 property_set(persist_key, "TRUE");
1683 property_get(persist_key, persist, "");
1684 uid_t uid = getuid();
1685 gid_t gid = getgid();
1686 bool perm = (gid == AID_ROOT) || (uid == AID_ROOT);
1687 EXPECT_STREQ(perm ? "TRUE" : persist_hold, persist);
1688 if (!strcasecmp(persist, "true")) {
1689 EXPECT_TRUE(__android_log_security());
1690 } else {
1691 EXPECT_FALSE(__android_log_security());
1692 }
1693 property_set(persist_key, "FALSE");
1694 property_get(persist_key, persist, "");
1695 EXPECT_STREQ(perm ? "FALSE" : persist_hold, persist);
1696 if (!strcasecmp(persist, "true")) {
1697 EXPECT_TRUE(__android_log_security());
1698 } else {
1699 EXPECT_FALSE(__android_log_security());
1700 }
1701 property_set(persist_key, "true");
1702 property_get(persist_key, persist, "");
1703 EXPECT_STREQ(perm ? "true" : persist_hold, persist);
1704 if (!strcasecmp(persist, "true")) {
1705 EXPECT_TRUE(__android_log_security());
1706 } else {
1707 EXPECT_FALSE(__android_log_security());
1708 }
1709 property_set(persist_key, "false");
1710 property_get(persist_key, persist, "");
1711 EXPECT_STREQ(perm ? "false" : persist_hold, persist);
1712 if (!strcasecmp(persist, "true")) {
1713 EXPECT_TRUE(__android_log_security());
1714 } else {
1715 EXPECT_FALSE(__android_log_security());
1716 }
1717 property_set(persist_key, "");
1718 property_get(persist_key, persist, "");
1719 EXPECT_STREQ(perm ? "" : persist_hold, persist);
1720 if (!strcasecmp(persist, "true")) {
1721 EXPECT_TRUE(__android_log_security());
1722 } else {
1723 EXPECT_FALSE(__android_log_security());
1724 }
1725 property_set(persist_key, persist_hold);
1726 property_get(persist_key, persist, "");
1727 EXPECT_STREQ(persist_hold, persist);
1728 #else
1729 GTEST_LOG_(INFO) << "This test does nothing.\n";
1730 #endif
1731 }
1732
TEST(liblog,__security_buffer)1733 TEST(liblog, __security_buffer) {
1734 #ifdef __ANDROID__
1735 struct logger_list* logger_list;
1736 android_event_long_t buffer;
1737
1738 static const char persist_key[] = "persist.logd.security";
1739 char persist[PROP_VALUE_MAX];
1740 bool set_persist = false;
1741 bool allow_security = false;
1742
1743 if (__android_log_security()) {
1744 allow_security = true;
1745 } else {
1746 property_get(persist_key, persist, "");
1747 if (strcasecmp(persist, "true")) {
1748 property_set(persist_key, "TRUE");
1749 if (__android_log_security()) {
1750 allow_security = true;
1751 set_persist = true;
1752 } else {
1753 property_set(persist_key, persist);
1754 }
1755 }
1756 }
1757
1758 if (!allow_security) {
1759 fprintf(stderr,
1760 "WARNING: "
1761 "security buffer disabled, bypassing end-to-end test\n");
1762
1763 log_time ts(CLOCK_MONOTONIC);
1764
1765 buffer.type = EVENT_TYPE_LONG;
1766 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
1767
1768 // expect failure!
1769 ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
1770
1771 return;
1772 }
1773
1774 /* Matches clientHasLogCredentials() in logd */
1775 uid_t uid = getuid();
1776 gid_t gid = getgid();
1777 bool clientHasLogCredentials = true;
1778 if ((uid != AID_SYSTEM) && (uid != AID_ROOT) && (uid != AID_LOG) &&
1779 (gid != AID_SYSTEM) && (gid != AID_ROOT) && (gid != AID_LOG)) {
1780 uid_t euid = geteuid();
1781 if ((euid != AID_SYSTEM) && (euid != AID_ROOT) && (euid != AID_LOG)) {
1782 gid_t egid = getegid();
1783 if ((egid != AID_SYSTEM) && (egid != AID_ROOT) && (egid != AID_LOG)) {
1784 int num_groups = getgroups(0, NULL);
1785 if (num_groups > 0) {
1786 gid_t groups[num_groups];
1787 num_groups = getgroups(num_groups, groups);
1788 while (num_groups > 0) {
1789 if (groups[num_groups - 1] == AID_LOG) {
1790 break;
1791 }
1792 --num_groups;
1793 }
1794 }
1795 if (num_groups <= 0) {
1796 clientHasLogCredentials = false;
1797 }
1798 }
1799 }
1800 }
1801 if (!clientHasLogCredentials) {
1802 fprintf(stderr,
1803 "WARNING: "
1804 "not in system context, bypassing end-to-end test\n");
1805
1806 log_time ts(CLOCK_MONOTONIC);
1807
1808 buffer.type = EVENT_TYPE_LONG;
1809 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
1810
1811 // expect failure!
1812 ASSERT_GE(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
1813
1814 return;
1815 }
1816
1817 EXPECT_EQ(0, setuid(AID_SYSTEM)); // only one that can read security buffer
1818
1819 uid = getuid();
1820 gid = getgid();
1821 pid_t pid = getpid();
1822
1823 ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(LOG_ID_SECURITY, ANDROID_LOG_NONBLOCK,
1824 1000, pid)));
1825
1826 log_time ts(CLOCK_MONOTONIC);
1827
1828 buffer.type = EVENT_TYPE_LONG;
1829 buffer.data = *(static_cast<uint64_t*>((void*)&ts));
1830
1831 ASSERT_LT(0, __android_log_security_bwrite(0, &buffer, sizeof(buffer)));
1832 usleep(1000000);
1833
1834 int count = 0;
1835
1836 for (;;) {
1837 log_msg log_msg;
1838 if (android_logger_list_read(logger_list, &log_msg) <= 0) {
1839 break;
1840 }
1841
1842 ASSERT_EQ(log_msg.entry.pid, pid);
1843
1844 if ((log_msg.entry.len != sizeof(android_log_event_long_t)) ||
1845 (log_msg.id() != LOG_ID_SECURITY)) {
1846 continue;
1847 }
1848
1849 android_log_event_long_t* eventData;
1850 eventData = reinterpret_cast<android_log_event_long_t*>(log_msg.msg());
1851
1852 if (!eventData || (eventData->payload.type != EVENT_TYPE_LONG)) {
1853 continue;
1854 }
1855
1856 log_time tx(reinterpret_cast<char*>(&eventData->payload.data));
1857 if (ts == tx) {
1858 ++count;
1859 }
1860 }
1861
1862 if (set_persist) {
1863 property_set(persist_key, persist);
1864 }
1865
1866 android_logger_list_close(logger_list);
1867
1868 bool clientHasSecurityCredentials = (uid == AID_SYSTEM) || (gid == AID_SYSTEM);
1869 if (!clientHasSecurityCredentials) {
1870 fprintf(stderr,
1871 "WARNING: "
1872 "not system, content submitted but can not check end-to-end\n");
1873 }
1874 EXPECT_EQ(clientHasSecurityCredentials ? 1 : 0, count);
1875 #else
1876 GTEST_LOG_(INFO) << "This test does nothing.\n";
1877 #endif
1878 }
1879 #endif // ENABLE_FLAKY_TESTS
1880
1881 #ifdef __ANDROID__
android_errorWriteWithInfoLog_helper(int tag,const char * subtag,int uid,const char * payload,int data_len)1882 static void android_errorWriteWithInfoLog_helper(int tag, const char* subtag, int uid,
1883 const char* payload, int data_len) {
1884 auto write_function = [&] {
1885 int ret = android_errorWriteWithInfoLog(tag, subtag, uid, payload, data_len);
1886 ASSERT_LT(0, ret);
1887 };
1888
1889 auto check_function = [&](log_msg log_msg, bool* found) {
1890 char* event_data = log_msg.msg();
1891 char* original = event_data;
1892
1893 // Tag
1894 auto* event_header = reinterpret_cast<android_event_header_t*>(event_data);
1895 event_data += sizeof(android_event_header_t);
1896 if (event_header->tag != tag) {
1897 return;
1898 }
1899
1900 // List type
1901 auto* event_list = reinterpret_cast<android_event_list_t*>(event_data);
1902 ASSERT_EQ(EVENT_TYPE_LIST, event_list->type);
1903 ASSERT_EQ(3, event_list->element_count);
1904 event_data += sizeof(android_event_list_t);
1905
1906 // Element #1: string type for subtag
1907 auto* event_string_subtag = reinterpret_cast<android_event_string_t*>(event_data);
1908 ASSERT_EQ(EVENT_TYPE_STRING, event_string_subtag->type);
1909 int32_t subtag_len = strlen(subtag);
1910 if (subtag_len > 32) {
1911 subtag_len = 32;
1912 }
1913 ASSERT_EQ(subtag_len, event_string_subtag->length);
1914 if (memcmp(subtag, &event_string_subtag->data, subtag_len)) {
1915 return;
1916 }
1917 event_data += sizeof(android_event_string_t) + subtag_len;
1918
1919 // Element #2: int type for uid
1920 auto* event_int_uid = reinterpret_cast<android_event_int_t*>(event_data);
1921 ASSERT_EQ(EVENT_TYPE_INT, event_int_uid->type);
1922 ASSERT_EQ(uid, event_int_uid->data);
1923 event_data += sizeof(android_event_int_t);
1924
1925 // Element #3: string type for data
1926 auto* event_string_data = reinterpret_cast<android_event_string_t*>(event_data);
1927 ASSERT_EQ(EVENT_TYPE_STRING, event_string_data->type);
1928 int32_t message_data_len = event_string_data->length;
1929 if (data_len < 512) {
1930 ASSERT_EQ(data_len, message_data_len);
1931 }
1932 if (memcmp(payload, &event_string_data->data, message_data_len) != 0) {
1933 return;
1934 }
1935 event_data += sizeof(android_event_string_t);
1936
1937 if (data_len >= 512) {
1938 event_data += message_data_len;
1939 // 4 bytes for the tag, and max_payload_buf should be truncated.
1940 ASSERT_LE(4 + 512, event_data - original); // worst expectations
1941 ASSERT_GT(4 + data_len, event_data - original); // must be truncated
1942 }
1943 *found = true;
1944 };
1945
1946 RunLogTests(LOG_ID_EVENTS, write_function, check_function);
1947 }
1948 #endif
1949
1950 // Make multiple tests and re-tests orthogonal to prevent falsing.
1951 #ifdef TEST_LOGGER
1952 #define UNIQUE_TAG(X) \
1953 (0x12340000 + (((X) + sizeof(int) + sizeof(void*)) << 8) + TEST_LOGGER)
1954 #else
1955 #define UNIQUE_TAG(X) \
1956 (0x12340000 + (((X) + sizeof(int) + sizeof(void*)) << 8) + 0xBA)
1957 #endif
1958
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__typical)1959 TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__typical) {
1960 #ifdef __ANDROID__
1961 android_errorWriteWithInfoLog_helper(UNIQUE_TAG(1), "test-subtag", -1, max_payload_buf, 200);
1962 #else
1963 GTEST_LOG_(INFO) << "This test does nothing.\n";
1964 #endif
1965 }
1966
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__data_too_large)1967 TEST(liblog,
1968 android_errorWriteWithInfoLog__android_logger_list_read__data_too_large) {
1969 #ifdef __ANDROID__
1970 android_errorWriteWithInfoLog_helper(UNIQUE_TAG(2), "test-subtag", -1, max_payload_buf,
1971 sizeof(max_payload_buf));
1972 #else
1973 GTEST_LOG_(INFO) << "This test does nothing.\n";
1974 #endif
1975 }
1976
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__null_data)1977 TEST(liblog,
1978 android_errorWriteWithInfoLog__android_logger_list_read__null_data) {
1979 #ifdef __ANDROID__
1980 int retval_android_errorWriteWithinInfoLog =
1981 android_errorWriteWithInfoLog(UNIQUE_TAG(3), "test-subtag", -1, nullptr, 200);
1982 ASSERT_GT(0, retval_android_errorWriteWithinInfoLog);
1983 #else
1984 GTEST_LOG_(INFO) << "This test does nothing.\n";
1985 #endif
1986 }
1987
TEST(liblog,android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long)1988 TEST(liblog,
1989 android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long) {
1990 #ifdef __ANDROID__
1991 android_errorWriteWithInfoLog_helper(
1992 UNIQUE_TAG(4), "abcdefghijklmnopqrstuvwxyz now i know my abc", -1, max_payload_buf, 200);
1993 #else
1994 GTEST_LOG_(INFO) << "This test does nothing.\n";
1995 #endif
1996 }
1997
TEST(liblog,__android_log_bswrite_and_print___max)1998 TEST(liblog, __android_log_bswrite_and_print___max) {
1999 bswrite_test(max_payload_buf);
2000 }
2001
TEST(liblog,__android_log_buf_write_and_print__max)2002 TEST(liblog, __android_log_buf_write_and_print__max) {
2003 buf_write_test(max_payload_buf);
2004 }
2005
TEST(liblog,android_errorWriteLog__android_logger_list_read__success)2006 TEST(liblog, android_errorWriteLog__android_logger_list_read__success) {
2007 #ifdef __ANDROID__
2008 int kTag = UNIQUE_TAG(5);
2009 const char* kSubTag = "test-subtag";
2010
2011 auto write_function = [&] {
2012 int retval_android_errorWriteLog = android_errorWriteLog(kTag, kSubTag);
2013 ASSERT_LT(0, retval_android_errorWriteLog);
2014 };
2015
2016 auto check_function = [&](log_msg log_msg, bool* found) {
2017 char* event_data = log_msg.msg();
2018
2019 // Tag
2020 auto* event_header = reinterpret_cast<android_event_header_t*>(event_data);
2021 event_data += sizeof(android_event_header_t);
2022 if (event_header->tag != kTag) {
2023 return;
2024 }
2025
2026 // List type
2027 auto* event_list = reinterpret_cast<android_event_list_t*>(event_data);
2028 ASSERT_EQ(EVENT_TYPE_LIST, event_list->type);
2029 ASSERT_EQ(3, event_list->element_count);
2030 event_data += sizeof(android_event_list_t);
2031
2032 // Element #1: string type for subtag
2033 auto* event_string_subtag = reinterpret_cast<android_event_string_t*>(event_data);
2034 ASSERT_EQ(EVENT_TYPE_STRING, event_string_subtag->type);
2035 int32_t subtag_len = strlen(kSubTag);
2036 ASSERT_EQ(subtag_len, event_string_subtag->length);
2037 if (memcmp(kSubTag, &event_string_subtag->data, subtag_len) == 0) {
2038 *found = true;
2039 }
2040 };
2041
2042 RunLogTests(LOG_ID_EVENTS, write_function, check_function);
2043
2044 #else
2045 GTEST_LOG_(INFO) << "This test does nothing.\n";
2046 #endif
2047 }
2048
TEST(liblog,android_errorWriteLog__android_logger_list_read__null_subtag)2049 TEST(liblog, android_errorWriteLog__android_logger_list_read__null_subtag) {
2050 #ifdef __ANDROID__
2051 EXPECT_LT(android_errorWriteLog(UNIQUE_TAG(6), nullptr), 0);
2052 #else
2053 GTEST_LOG_(INFO) << "This test does nothing.\n";
2054 #endif
2055 }
2056
2057 // Do not retest logger list handling
2058 #ifdef __ANDROID__
is_real_element(int type)2059 static int is_real_element(int type) {
2060 return ((type == EVENT_TYPE_INT) || (type == EVENT_TYPE_LONG) ||
2061 (type == EVENT_TYPE_STRING) || (type == EVENT_TYPE_FLOAT));
2062 }
2063
android_log_buffer_to_string(const char * msg,size_t len,char * strOut,size_t strOutLen)2064 static int android_log_buffer_to_string(const char* msg, size_t len,
2065 char* strOut, size_t strOutLen) {
2066 android_log_context context = create_android_log_parser(msg, len);
2067 android_log_list_element elem;
2068 bool overflow = false;
2069 /* Reserve 1 byte for null terminator. */
2070 size_t origStrOutLen = strOutLen--;
2071
2072 if (!context) {
2073 return -EBADF;
2074 }
2075
2076 memset(&elem, 0, sizeof(elem));
2077
2078 size_t outCount;
2079
2080 do {
2081 elem = android_log_read_next(context);
2082 switch ((int)elem.type) {
2083 case EVENT_TYPE_LIST:
2084 if (strOutLen == 0) {
2085 overflow = true;
2086 } else {
2087 *strOut++ = '[';
2088 strOutLen--;
2089 }
2090 break;
2091
2092 case EVENT_TYPE_LIST_STOP:
2093 if (strOutLen == 0) {
2094 overflow = true;
2095 } else {
2096 *strOut++ = ']';
2097 strOutLen--;
2098 }
2099 break;
2100
2101 case EVENT_TYPE_INT:
2102 /*
2103 * snprintf also requires room for the null terminator, which
2104 * we don't care about but we have allocated enough room for
2105 * that
2106 */
2107 outCount = snprintf(strOut, strOutLen + 1, "%" PRId32, elem.data.int32);
2108 if (outCount <= strOutLen) {
2109 strOut += outCount;
2110 strOutLen -= outCount;
2111 } else {
2112 overflow = true;
2113 }
2114 break;
2115
2116 case EVENT_TYPE_LONG:
2117 /*
2118 * snprintf also requires room for the null terminator, which
2119 * we don't care about but we have allocated enough room for
2120 * that
2121 */
2122 outCount = snprintf(strOut, strOutLen + 1, "%" PRId64, elem.data.int64);
2123 if (outCount <= strOutLen) {
2124 strOut += outCount;
2125 strOutLen -= outCount;
2126 } else {
2127 overflow = true;
2128 }
2129 break;
2130
2131 case EVENT_TYPE_FLOAT:
2132 /*
2133 * snprintf also requires room for the null terminator, which
2134 * we don't care about but we have allocated enough room for
2135 * that
2136 */
2137 outCount = snprintf(strOut, strOutLen + 1, "%f", elem.data.float32);
2138 if (outCount <= strOutLen) {
2139 strOut += outCount;
2140 strOutLen -= outCount;
2141 } else {
2142 overflow = true;
2143 }
2144 break;
2145
2146 default:
2147 elem.complete = true;
2148 break;
2149
2150 case EVENT_TYPE_UNKNOWN:
2151 #if 0 // Ideal purity in the test, we want to complain about UNKNOWN showing up
2152 if (elem.complete) {
2153 break;
2154 }
2155 #endif
2156 elem.data.string = const_cast<char*>("<unknown>");
2157 elem.len = strlen(elem.data.string);
2158 FALLTHROUGH_INTENDED;
2159 case EVENT_TYPE_STRING:
2160 if (elem.len <= strOutLen) {
2161 memcpy(strOut, elem.data.string, elem.len);
2162 strOut += elem.len;
2163 strOutLen -= elem.len;
2164 } else if (strOutLen > 0) {
2165 /* copy what we can */
2166 memcpy(strOut, elem.data.string, strOutLen);
2167 strOut += strOutLen;
2168 strOutLen = 0;
2169 overflow = true;
2170 }
2171 break;
2172 }
2173
2174 if (elem.complete) {
2175 break;
2176 }
2177 /* Determine whether to put a comma or not. */
2178 if (!overflow &&
2179 (is_real_element(elem.type) || (elem.type == EVENT_TYPE_LIST_STOP))) {
2180 android_log_list_element next = android_log_peek_next(context);
2181 if (!next.complete &&
2182 (is_real_element(next.type) || (next.type == EVENT_TYPE_LIST))) {
2183 if (strOutLen == 0) {
2184 overflow = true;
2185 } else {
2186 *strOut++ = ',';
2187 strOutLen--;
2188 }
2189 }
2190 }
2191 } while ((elem.type != EVENT_TYPE_UNKNOWN) && !overflow && !elem.complete);
2192
2193 android_log_destroy(&context);
2194
2195 if (overflow) {
2196 if (strOutLen < origStrOutLen) {
2197 /* leave an indicator */
2198 *(strOut - 1) = '!';
2199 } else {
2200 /* nothing was written at all */
2201 *strOut++ = '!';
2202 }
2203 }
2204 *strOut++ = '\0';
2205
2206 if ((elem.type == EVENT_TYPE_UNKNOWN) && !elem.complete) {
2207 fprintf(stderr, "Binary log entry conversion failed\n");
2208 return -EINVAL;
2209 }
2210
2211 return 0;
2212 }
2213 #endif // __ANDROID__
2214
2215 #ifdef __ANDROID__
event_test_int32(uint32_t tag,size_t & expected_len)2216 static const char* event_test_int32(uint32_t tag, size_t& expected_len) {
2217 android_log_context ctx;
2218
2219 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2220 if (!ctx) {
2221 return NULL;
2222 }
2223 EXPECT_LE(0, android_log_write_int32(ctx, 0x40302010));
2224 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2225 EXPECT_LE(0, android_log_destroy(&ctx));
2226 EXPECT_TRUE(NULL == ctx);
2227
2228 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint32_t);
2229
2230 return "1076895760";
2231 }
2232
event_test_int64(uint32_t tag,size_t & expected_len)2233 static const char* event_test_int64(uint32_t tag, size_t& expected_len) {
2234 android_log_context ctx;
2235
2236 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2237 if (!ctx) {
2238 return NULL;
2239 }
2240 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2241 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2242 EXPECT_LE(0, android_log_destroy(&ctx));
2243 EXPECT_TRUE(NULL == ctx);
2244
2245 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint64_t);
2246
2247 return "-9191740941672636400";
2248 }
2249
event_test_list_int64(uint32_t tag,size_t & expected_len)2250 static const char* event_test_list_int64(uint32_t tag, size_t& expected_len) {
2251 android_log_context ctx;
2252
2253 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2254 if (!ctx) {
2255 return NULL;
2256 }
2257 EXPECT_LE(0, android_log_write_list_begin(ctx));
2258 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2259 EXPECT_LE(0, android_log_write_list_end(ctx));
2260 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2261 EXPECT_LE(0, android_log_destroy(&ctx));
2262 EXPECT_TRUE(NULL == ctx);
2263
2264 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2265 sizeof(uint8_t) + sizeof(uint64_t);
2266
2267 return "[-9191740941672636400]";
2268 }
2269
event_test_simple_automagic_list(uint32_t tag,size_t & expected_len)2270 static const char* event_test_simple_automagic_list(uint32_t tag,
2271 size_t& expected_len) {
2272 android_log_context ctx;
2273
2274 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2275 if (!ctx) {
2276 return NULL;
2277 }
2278 // The convenience API where we allow a simple list to be
2279 // created without explicit begin or end calls.
2280 EXPECT_LE(0, android_log_write_int32(ctx, 0x40302010));
2281 EXPECT_LE(0, android_log_write_int64(ctx, 0x8070605040302010));
2282 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2283 EXPECT_LE(0, android_log_destroy(&ctx));
2284 EXPECT_TRUE(NULL == ctx);
2285
2286 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2287 sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2288 sizeof(uint64_t);
2289
2290 return "[1076895760,-9191740941672636400]";
2291 }
2292
event_test_list_empty(uint32_t tag,size_t & expected_len)2293 static const char* event_test_list_empty(uint32_t tag, size_t& expected_len) {
2294 android_log_context ctx;
2295
2296 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2297 if (!ctx) {
2298 return NULL;
2299 }
2300 EXPECT_LE(0, android_log_write_list_begin(ctx));
2301 EXPECT_LE(0, android_log_write_list_end(ctx));
2302 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2303 EXPECT_LE(0, android_log_destroy(&ctx));
2304 EXPECT_TRUE(NULL == ctx);
2305
2306 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t);
2307
2308 return "[]";
2309 }
2310
event_test_complex_nested_list(uint32_t tag,size_t & expected_len)2311 static const char* event_test_complex_nested_list(uint32_t tag,
2312 size_t& expected_len) {
2313 android_log_context ctx;
2314
2315 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2316 if (!ctx) {
2317 return NULL;
2318 }
2319
2320 EXPECT_LE(0, android_log_write_list_begin(ctx)); // [
2321 EXPECT_LE(0, android_log_write_int32(ctx, 0x01020304));
2322 EXPECT_LE(0, android_log_write_int64(ctx, 0x0102030405060708));
2323 EXPECT_LE(0, android_log_write_string8(ctx, "Hello World"));
2324 EXPECT_LE(0, android_log_write_list_begin(ctx)); // [
2325 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2326 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2327 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2328 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2329 EXPECT_LE(0, android_log_write_list_end(ctx)); // ]
2330 EXPECT_LE(0, android_log_write_float32(ctx, 1.0102030405060708));
2331 EXPECT_LE(0, android_log_write_list_end(ctx)); // ]
2332
2333 //
2334 // This one checks for the automagic list creation because a list
2335 // begin and end was missing for it! This is actually an <oops> corner
2336 // case, and not the behavior we morally support. The automagic API is to
2337 // allow for a simple case of a series of objects in a single list. e.g.
2338 // int32,int32,int32,string -> [int32,int32,int32,string]
2339 //
2340 EXPECT_LE(0, android_log_write_string8(ctx, "dlroW olleH"));
2341
2342 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2343 EXPECT_LE(0, android_log_destroy(&ctx));
2344 EXPECT_TRUE(NULL == ctx);
2345
2346 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2347 sizeof(uint8_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2348 sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint64_t) +
2349 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2350 1 + sizeof(uint8_t) + sizeof(uint8_t) +
2351 4 * (sizeof(uint8_t) + sizeof(uint32_t)) + sizeof(uint8_t) +
2352 sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint32_t) +
2353 sizeof("dlroW olleH") - 1;
2354
2355 return "[[16909060,72623859790382856,Hello World,[1,2,3,4],1.010203],dlroW "
2356 "olleH]";
2357 }
2358
event_test_7_level_prefix(uint32_t tag,size_t & expected_len)2359 static const char* event_test_7_level_prefix(uint32_t tag,
2360 size_t& expected_len) {
2361 android_log_context ctx;
2362
2363 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2364 if (!ctx) {
2365 return NULL;
2366 }
2367 EXPECT_LE(0, android_log_write_list_begin(ctx));
2368 EXPECT_LE(0, android_log_write_list_begin(ctx));
2369 EXPECT_LE(0, android_log_write_list_begin(ctx));
2370 EXPECT_LE(0, android_log_write_list_begin(ctx));
2371 EXPECT_LE(0, android_log_write_list_begin(ctx));
2372 EXPECT_LE(0, android_log_write_list_begin(ctx));
2373 EXPECT_LE(0, android_log_write_list_begin(ctx));
2374 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2375 EXPECT_LE(0, android_log_write_list_end(ctx));
2376 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2377 EXPECT_LE(0, android_log_write_list_end(ctx));
2378 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2379 EXPECT_LE(0, android_log_write_list_end(ctx));
2380 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2381 EXPECT_LE(0, android_log_write_list_end(ctx));
2382 EXPECT_LE(0, android_log_write_int32(ctx, 5));
2383 EXPECT_LE(0, android_log_write_list_end(ctx));
2384 EXPECT_LE(0, android_log_write_int32(ctx, 6));
2385 EXPECT_LE(0, android_log_write_list_end(ctx));
2386 EXPECT_LE(0, android_log_write_int32(ctx, 7));
2387 EXPECT_LE(0, android_log_write_list_end(ctx));
2388 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2389 EXPECT_LE(0, android_log_destroy(&ctx));
2390 EXPECT_TRUE(NULL == ctx);
2391
2392 expected_len = sizeof(uint32_t) + 7 * (sizeof(uint8_t) + sizeof(uint8_t) +
2393 sizeof(uint8_t) + sizeof(uint32_t));
2394
2395 return "[[[[[[[1],2],3],4],5],6],7]";
2396 }
2397
event_test_7_level_suffix(uint32_t tag,size_t & expected_len)2398 static const char* event_test_7_level_suffix(uint32_t tag,
2399 size_t& expected_len) {
2400 android_log_context ctx;
2401
2402 EXPECT_TRUE(NULL != (ctx = create_android_logger(tag)));
2403 if (!ctx) {
2404 return NULL;
2405 }
2406 EXPECT_LE(0, android_log_write_list_begin(ctx));
2407 EXPECT_LE(0, android_log_write_int32(ctx, 1));
2408 EXPECT_LE(0, android_log_write_list_begin(ctx));
2409 EXPECT_LE(0, android_log_write_int32(ctx, 2));
2410 EXPECT_LE(0, android_log_write_list_begin(ctx));
2411 EXPECT_LE(0, android_log_write_int32(ctx, 3));
2412 EXPECT_LE(0, android_log_write_list_begin(ctx));
2413 EXPECT_LE(0, android_log_write_int32(ctx, 4));
2414 EXPECT_LE(0, android_log_write_list_begin(ctx));
2415 EXPECT_LE(0, android_log_write_int32(ctx, 5));
2416 EXPECT_LE(0, android_log_write_list_begin(ctx));
2417 EXPECT_LE(0, android_log_write_int32(ctx, 6));
2418 EXPECT_LE(0, android_log_write_list_end(ctx));
2419 EXPECT_LE(0, android_log_write_list_end(ctx));
2420 EXPECT_LE(0, android_log_write_list_end(ctx));
2421 EXPECT_LE(0, android_log_write_list_end(ctx));
2422 EXPECT_LE(0, android_log_write_list_end(ctx));
2423 EXPECT_LE(0, android_log_write_list_end(ctx));
2424 EXPECT_LE(0, android_log_write_list(ctx, LOG_ID_EVENTS));
2425 EXPECT_LE(0, android_log_destroy(&ctx));
2426 EXPECT_TRUE(NULL == ctx);
2427
2428 expected_len = sizeof(uint32_t) + 6 * (sizeof(uint8_t) + sizeof(uint8_t) +
2429 sizeof(uint8_t) + sizeof(uint32_t));
2430
2431 return "[1,[2,[3,[4,[5,[6]]]]]]";
2432 }
2433
event_test_android_log_error_write(uint32_t tag,size_t & expected_len)2434 static const char* event_test_android_log_error_write(uint32_t tag,
2435 size_t& expected_len) {
2436 EXPECT_LE(
2437 0, __android_log_error_write(tag, "Hello World", 42, "dlroW olleH", 11));
2438
2439 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2440 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2441 1 + sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2442 sizeof(uint32_t) + sizeof("dlroW olleH") - 1;
2443
2444 return "[Hello World,42,dlroW olleH]";
2445 }
2446
event_test_android_log_error_write_null(uint32_t tag,size_t & expected_len)2447 static const char* event_test_android_log_error_write_null(uint32_t tag,
2448 size_t& expected_len) {
2449 EXPECT_LE(0, __android_log_error_write(tag, "Hello World", 42, NULL, 0));
2450
2451 expected_len = sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint8_t) +
2452 sizeof(uint8_t) + sizeof(uint32_t) + sizeof("Hello World") -
2453 1 + sizeof(uint8_t) + sizeof(uint32_t) + sizeof(uint8_t) +
2454 sizeof(uint32_t) + sizeof("") - 1;
2455
2456 return "[Hello World,42,]";
2457 }
2458
2459 // make sure all user buffers are flushed
print_barrier()2460 static void print_barrier() {
2461 std::cout.flush();
2462 fflush(stdout);
2463 std::cerr.flush();
2464 fflush(stderr); // everything else is paranoia ...
2465 }
2466
create_android_logger(const char * (* fn)(uint32_t tag,size_t & expected_len))2467 static void create_android_logger(const char* (*fn)(uint32_t tag,
2468 size_t& expected_len)) {
2469 size_t expected_len;
2470 const char* expected_string;
2471 auto write_function = [&] {
2472 expected_string = (*fn)(1005, expected_len);
2473 ASSERT_NE(nullptr, expected_string);
2474 };
2475
2476 pid_t pid = getpid();
2477 auto check_function = [&](log_msg log_msg, bool* found) {
2478 if (static_cast<size_t>(log_msg.entry.len) != expected_len) {
2479 return;
2480 }
2481
2482 char* eventData = log_msg.msg();
2483
2484 AndroidLogFormat* logformat = android_log_format_new();
2485 EXPECT_TRUE(NULL != logformat);
2486 AndroidLogEntry entry;
2487 char msgBuf[1024];
2488 int processBinaryLogBuffer =
2489 android_log_processBinaryLogBuffer(&log_msg.entry, &entry, nullptr, msgBuf, sizeof(msgBuf));
2490 EXPECT_EQ(0, processBinaryLogBuffer);
2491 if (processBinaryLogBuffer == 0) {
2492 int line_overhead = 20;
2493 if (pid > 99999) ++line_overhead;
2494 if (pid > 999999) ++line_overhead;
2495 print_barrier();
2496 int printLogLine =
2497 android_log_printLogLine(logformat, fileno(stderr), &entry);
2498 print_barrier();
2499 EXPECT_EQ(line_overhead + (int)strlen(expected_string), printLogLine);
2500 }
2501 android_log_format_free(logformat);
2502
2503 // test buffer reading API
2504 int buffer_to_string = -1;
2505 if (eventData) {
2506 auto* event_header = reinterpret_cast<android_event_header_t*>(eventData);
2507 eventData += sizeof(android_event_header_t);
2508 snprintf(msgBuf, sizeof(msgBuf), "I/[%" PRId32 "]", event_header->tag);
2509 print_barrier();
2510 fprintf(stderr, "%-10s(%5u): ", msgBuf, pid);
2511 memset(msgBuf, 0, sizeof(msgBuf));
2512 buffer_to_string =
2513 android_log_buffer_to_string(eventData, log_msg.entry.len, msgBuf, sizeof(msgBuf));
2514 fprintf(stderr, "%s\n", msgBuf);
2515 print_barrier();
2516 }
2517 EXPECT_EQ(0, buffer_to_string);
2518 EXPECT_STREQ(expected_string, msgBuf);
2519 *found = true;
2520 };
2521
2522 RunLogTests(LOG_ID_EVENTS, write_function, check_function);
2523 }
2524 #endif
2525
TEST(liblog,create_android_logger_int32)2526 TEST(liblog, create_android_logger_int32) {
2527 #ifdef __ANDROID__
2528 create_android_logger(event_test_int32);
2529 #else
2530 GTEST_LOG_(INFO) << "This test does nothing.\n";
2531 #endif
2532 }
2533
TEST(liblog,create_android_logger_int64)2534 TEST(liblog, create_android_logger_int64) {
2535 #ifdef __ANDROID__
2536 create_android_logger(event_test_int64);
2537 #else
2538 GTEST_LOG_(INFO) << "This test does nothing.\n";
2539 #endif
2540 }
2541
TEST(liblog,create_android_logger_list_int64)2542 TEST(liblog, create_android_logger_list_int64) {
2543 #ifdef __ANDROID__
2544 create_android_logger(event_test_list_int64);
2545 #else
2546 GTEST_LOG_(INFO) << "This test does nothing.\n";
2547 #endif
2548 }
2549
TEST(liblog,create_android_logger_simple_automagic_list)2550 TEST(liblog, create_android_logger_simple_automagic_list) {
2551 #ifdef __ANDROID__
2552 create_android_logger(event_test_simple_automagic_list);
2553 #else
2554 GTEST_LOG_(INFO) << "This test does nothing.\n";
2555 #endif
2556 }
2557
TEST(liblog,create_android_logger_list_empty)2558 TEST(liblog, create_android_logger_list_empty) {
2559 #ifdef __ANDROID__
2560 create_android_logger(event_test_list_empty);
2561 #else
2562 GTEST_LOG_(INFO) << "This test does nothing.\n";
2563 #endif
2564 }
2565
TEST(liblog,create_android_logger_complex_nested_list)2566 TEST(liblog, create_android_logger_complex_nested_list) {
2567 #ifdef __ANDROID__
2568 create_android_logger(event_test_complex_nested_list);
2569 #else
2570 GTEST_LOG_(INFO) << "This test does nothing.\n";
2571 #endif
2572 }
2573
TEST(liblog,create_android_logger_7_level_prefix)2574 TEST(liblog, create_android_logger_7_level_prefix) {
2575 #ifdef __ANDROID__
2576 create_android_logger(event_test_7_level_prefix);
2577 #else
2578 GTEST_LOG_(INFO) << "This test does nothing.\n";
2579 #endif
2580 }
2581
TEST(liblog,create_android_logger_7_level_suffix)2582 TEST(liblog, create_android_logger_7_level_suffix) {
2583 #ifdef __ANDROID__
2584 create_android_logger(event_test_7_level_suffix);
2585 #else
2586 GTEST_LOG_(INFO) << "This test does nothing.\n";
2587 #endif
2588 }
2589
TEST(liblog,create_android_logger_android_log_error_write)2590 TEST(liblog, create_android_logger_android_log_error_write) {
2591 #ifdef __ANDROID__
2592 create_android_logger(event_test_android_log_error_write);
2593 #else
2594 GTEST_LOG_(INFO) << "This test does nothing.\n";
2595 #endif
2596 }
2597
TEST(liblog,create_android_logger_android_log_error_write_null)2598 TEST(liblog, create_android_logger_android_log_error_write_null) {
2599 #ifdef __ANDROID__
2600 create_android_logger(event_test_android_log_error_write_null);
2601 #else
2602 GTEST_LOG_(INFO) << "This test does nothing.\n";
2603 #endif
2604 }
2605
TEST(liblog,create_android_logger_overflow)2606 TEST(liblog, create_android_logger_overflow) {
2607 android_log_context ctx;
2608
2609 EXPECT_TRUE(NULL != (ctx = create_android_logger(1005)));
2610 if (ctx) {
2611 for (size_t i = 0; i < ANDROID_MAX_LIST_NEST_DEPTH; ++i) {
2612 EXPECT_LE(0, android_log_write_list_begin(ctx));
2613 }
2614 EXPECT_GT(0, android_log_write_list_begin(ctx));
2615 /* One more for good measure, must be permanently unhappy */
2616 EXPECT_GT(0, android_log_write_list_begin(ctx));
2617 EXPECT_LE(0, android_log_destroy(&ctx));
2618 EXPECT_TRUE(NULL == ctx);
2619 }
2620
2621 ASSERT_TRUE(NULL != (ctx = create_android_logger(1005)));
2622 for (size_t i = 0; i < ANDROID_MAX_LIST_NEST_DEPTH; ++i) {
2623 EXPECT_LE(0, android_log_write_list_begin(ctx));
2624 EXPECT_LE(0, android_log_write_int32(ctx, i));
2625 }
2626 EXPECT_GT(0, android_log_write_list_begin(ctx));
2627 /* One more for good measure, must be permanently unhappy */
2628 EXPECT_GT(0, android_log_write_list_begin(ctx));
2629 EXPECT_LE(0, android_log_destroy(&ctx));
2630 ASSERT_TRUE(NULL == ctx);
2631 }
2632
2633 #ifdef ENABLE_FLAKY_TESTS
2634 #ifdef __ANDROID__
2635 #ifndef NO_PSTORE
2636 static const char __pmsg_file[] =
2637 "/data/william-shakespeare/MuchAdoAboutNothing.txt";
2638 #endif /* NO_PSTORE */
2639 #endif
2640
TEST(liblog,__android_log_pmsg_file_write)2641 TEST(liblog, __android_log_pmsg_file_write) {
2642 #ifdef __ANDROID__
2643 #ifndef NO_PSTORE
2644 __android_log_close();
2645 if (getuid() == AID_ROOT) {
2646 tested__android_log_close = true;
2647 bool pmsgActiveAfter__android_log_close = isPmsgActive();
2648 bool logdwActiveAfter__android_log_close = isLogdwActive();
2649 EXPECT_FALSE(pmsgActiveAfter__android_log_close);
2650 EXPECT_FALSE(logdwActiveAfter__android_log_close);
2651 } else if (!tested__android_log_close) {
2652 fprintf(stderr, "WARNING: can not test __android_log_close()\n");
2653 }
2654 int return__android_log_pmsg_file_write = __android_log_pmsg_file_write(
2655 LOG_ID_CRASH, ANDROID_LOG_VERBOSE, __pmsg_file, max_payload_buf,
2656 sizeof(max_payload_buf));
2657 EXPECT_LT(0, return__android_log_pmsg_file_write);
2658 if (return__android_log_pmsg_file_write == -ENOMEM) {
2659 fprintf(stderr,
2660 "Kernel does not have space allocated to pmsg pstore driver "
2661 "configured\n");
2662 } else if (!return__android_log_pmsg_file_write) {
2663 fprintf(stderr,
2664 "Reboot, ensure file %s matches\n"
2665 "with liblog.__android_log_msg_file_read test\n",
2666 __pmsg_file);
2667 }
2668 bool pmsgActiveAfter__android_pmsg_file_write;
2669 bool logdwActiveAfter__android_pmsg_file_write;
2670 if (getuid() == AID_ROOT) {
2671 pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
2672 logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
2673 EXPECT_FALSE(pmsgActiveAfter__android_pmsg_file_write);
2674 EXPECT_FALSE(logdwActiveAfter__android_pmsg_file_write);
2675 }
2676 EXPECT_LT(
2677 0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
2678 "TEST__android_log_pmsg_file_write", "main"));
2679 if (getuid() == AID_ROOT) {
2680 bool pmsgActiveAfter__android_log_buf_print = isPmsgActive();
2681 bool logdwActiveAfter__android_log_buf_print = isLogdwActive();
2682 EXPECT_TRUE(pmsgActiveAfter__android_log_buf_print);
2683 EXPECT_TRUE(logdwActiveAfter__android_log_buf_print);
2684 }
2685 EXPECT_LT(0, __android_log_pmsg_file_write(LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
2686 __pmsg_file, max_payload_buf,
2687 sizeof(max_payload_buf)));
2688 if (getuid() == AID_ROOT) {
2689 pmsgActiveAfter__android_pmsg_file_write = isPmsgActive();
2690 logdwActiveAfter__android_pmsg_file_write = isLogdwActive();
2691 EXPECT_TRUE(pmsgActiveAfter__android_pmsg_file_write);
2692 EXPECT_TRUE(logdwActiveAfter__android_pmsg_file_write);
2693 }
2694 #else /* NO_PSTORE */
2695 GTEST_LOG_(INFO) << "This test does nothing because of NO_PSTORE.\n";
2696 #endif /* NO_PSTORE */
2697 #else
2698 GTEST_LOG_(INFO) << "This test does nothing.\n";
2699 #endif
2700 }
2701
2702 #ifdef __ANDROID__
2703 #ifndef NO_PSTORE
__pmsg_fn(log_id_t logId,char prio,const char * filename,const char * buf,size_t len,void * arg)2704 static ssize_t __pmsg_fn(log_id_t logId, char prio, const char* filename,
2705 const char* buf, size_t len, void* arg) {
2706 EXPECT_TRUE(NULL == arg);
2707 EXPECT_EQ(LOG_ID_CRASH, logId);
2708 EXPECT_EQ(ANDROID_LOG_VERBOSE, prio);
2709 EXPECT_FALSE(NULL == strstr(__pmsg_file, filename));
2710 EXPECT_EQ(len, sizeof(max_payload_buf));
2711 EXPECT_STREQ(max_payload_buf, buf);
2712
2713 ++signaled;
2714 if ((len != sizeof(max_payload_buf)) || strcmp(max_payload_buf, buf)) {
2715 fprintf(stderr, "comparison fails on content \"%s\"\n", buf);
2716 }
2717 return arg || (LOG_ID_CRASH != logId) || (ANDROID_LOG_VERBOSE != prio) ||
2718 !strstr(__pmsg_file, filename) ||
2719 (len != sizeof(max_payload_buf)) ||
2720 !!strcmp(max_payload_buf, buf)
2721 ? -ENOEXEC
2722 : 1;
2723 }
2724 #endif /* NO_PSTORE */
2725 #endif
2726
TEST(liblog,__android_log_pmsg_file_read)2727 TEST(liblog, __android_log_pmsg_file_read) {
2728 #ifdef __ANDROID__
2729 #ifndef NO_PSTORE
2730 signaled = 0;
2731
2732 __android_log_close();
2733 if (getuid() == AID_ROOT) {
2734 tested__android_log_close = true;
2735 bool pmsgActiveAfter__android_log_close = isPmsgActive();
2736 bool logdwActiveAfter__android_log_close = isLogdwActive();
2737 EXPECT_FALSE(pmsgActiveAfter__android_log_close);
2738 EXPECT_FALSE(logdwActiveAfter__android_log_close);
2739 } else if (!tested__android_log_close) {
2740 fprintf(stderr, "WARNING: can not test __android_log_close()\n");
2741 }
2742
2743 ssize_t ret = __android_log_pmsg_file_read(LOG_ID_CRASH, ANDROID_LOG_VERBOSE,
2744 __pmsg_file, __pmsg_fn, NULL);
2745
2746 if (getuid() == AID_ROOT) {
2747 bool pmsgActiveAfter__android_log_pmsg_file_read = isPmsgActive();
2748 bool logdwActiveAfter__android_log_pmsg_file_read = isLogdwActive();
2749 EXPECT_FALSE(pmsgActiveAfter__android_log_pmsg_file_read);
2750 EXPECT_FALSE(logdwActiveAfter__android_log_pmsg_file_read);
2751 }
2752
2753 if (ret == -ENOENT) {
2754 fprintf(stderr,
2755 "No pre-boot results of liblog.__android_log_mesg_file_write to "
2756 "compare with,\n"
2757 "false positive test result.\n");
2758 return;
2759 }
2760
2761 EXPECT_LT(0, ret);
2762 EXPECT_EQ(1U, signaled);
2763 #else /* NO_PSTORE */
2764 GTEST_LOG_(INFO) << "This test does nothing because of NO_PSTORE.\n";
2765 #endif /* NO_PSTORE */
2766 #else
2767 GTEST_LOG_(INFO) << "This test does nothing.\n";
2768 #endif
2769 }
2770 #endif // ENABLE_FLAKY_TESTS
2771