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