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