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