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