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