1 /*
2 * Copyright (C) 2014 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 <errno.h>
19 #include <fcntl.h>
20 #include <inttypes.h>
21 #include <poll.h>
22 #include <signal.h>
23 #include <stdio.h>
24 #include <string.h>
25 #include <sys/stat.h>
26 #include <sys/types.h>
27 #include <unistd.h>
28
29 #include <string>
30
31 #include <android-base/file.h>
32 #include <android-base/macros.h>
33 #include <android-base/stringprintf.h>
34 #include <android-base/unique_fd.h>
35 #include <cutils/sockets.h>
36 #include <gtest/gtest-death-test.h>
37 #include <gtest/gtest.h>
38 #include <log/log_read.h>
39 #include <private/android_filesystem_config.h>
40 #include <private/android_logger.h>
41 #ifdef __ANDROID__
42 #include <selinux/selinux.h>
43 #endif
44
45 #include "LogUtils.h" // For LOGD_SNDTIMEO.
46
47 using android::base::unique_fd;
48
49 #ifdef __ANDROID__
write_command(int sock,const char * command)50 static bool write_command(int sock, const char* command) {
51 // The command sent to logd must include the '\0' character at the end.
52 size_t command_length = strlen(command) + 1;
53 ssize_t bytes_written = TEMP_FAILURE_RETRY(write(sock, command, command_length));
54 if (bytes_written != static_cast<ssize_t>(command_length)) {
55 if (bytes_written == -1) {
56 printf("Failed to send '%s' command: %s\n", command, strerror(errno));
57 } else {
58 printf("Failed to send '%s' command: bytes written %zd, expected written %zu\n",
59 command, bytes_written, command_length);
60 }
61 return false;
62 }
63 return true;
64 }
65
write_command(int sock,const std::string & command)66 static bool write_command(int sock, const std::string& command) {
67 return write_command(sock, command.c_str());
68 }
69
send_to_control(const char * command,std::string & result)70 static void send_to_control(const char* command, std::string& result) {
71 unique_fd sock(socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM));
72 ASSERT_LT(0, sock) << "Failed to open logd: " << strerror(errno);
73 ASSERT_TRUE(write_command(sock, command));
74 result.clear();
75 while (true) {
76 struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0};
77 // Timeout after 20 seconds.
78 int ret = TEMP_FAILURE_RETRY(poll(&p, 1, 20000));
79 ASSERT_TRUE(ret != -1) << "Poll call failed for command '" << command
80 << "': " << strerror(errno);
81 ASSERT_NE(0, ret) << "Timeout sending command '" << command << "'";
82 ASSERT_TRUE(p.revents & POLLIN)
83 << "Command socket not readable for command '" << command << "'";
84
85 char buffer[256];
86 ssize_t bytes_read = TEMP_FAILURE_RETRY(read(sock, buffer, sizeof(buffer)));
87 ASSERT_GE(bytes_read, 0) << "Read failed for command '" << command
88 << "': " << strerror(errno);
89 result += std::string(buffer, bytes_read);
90 if (bytes_read == 0 || static_cast<size_t>(bytes_read) < sizeof(buffer)) {
91 return;
92 }
93 }
94 }
95 #endif
96
97 #ifdef LOGD_ENABLE_FLAKY_TESTS
TEST(logd,statistics)98 TEST(logd, statistics) {
99 #ifdef __ANDROID__
100 // Drop cache so that any access problems can be discovered.
101 if (!android::base::WriteStringToFile("3\n", "/proc/sys/vm/drop_caches")) {
102 GTEST_LOG_(INFO) << "Could not open trigger dropping inode cache";
103 }
104
105 std::string result;
106 send_to_control("getStatistics 0 1 2 3 4", result);
107 ASSERT_FALSE(result.empty());
108
109 EXPECT_NE(std::string::npos, result.find("\nChattiest UIDs in main "));
110
111 EXPECT_NE(std::string::npos, result.find("\nChattiest UIDs in radio "));
112
113 EXPECT_NE(std::string::npos, result.find("\nChattiest UIDs in system "));
114
115 EXPECT_NE(std::string::npos, result.find("\nChattiest UIDs in events "));
116
117 // Look for any u0_a or u0_a[0-9]+ values. If found, it indicates the
118 // libpackagelistparser failed.
119 static const char getpwuid_prefix[] = " u0_a";
120 size_t pos = 0;
121 while ((pos = result.find(getpwuid_prefix, pos)) != std::string::npos) {
122 // Check to see if the value following u0_a is all digits, or empty.
123 size_t uid_name_pos = pos + strlen(getpwuid_prefix);
124 size_t i = 0;
125 while (isdigit(result[uid_name_pos + i])) {
126 i++;
127 }
128 ASSERT_FALSE(isspace(result[uid_name_pos + i]))
129 << "libpackagelistparser failed to pick up " << result.substr(uid_name_pos, i);
130
131 pos = uid_name_pos + i;
132 }
133 #else
134 GTEST_LOG_(INFO) << "This test does nothing.\n";
135 #endif
136 }
137 #endif
138
139 #ifdef __ANDROID__
caught_signal(int)140 static void caught_signal(int /* signum */) {
141 }
142
dump_log_msg(const char * prefix,log_msg * msg,int lid)143 static void dump_log_msg(const char* prefix, log_msg* msg, int lid) {
144 std::cout << std::flush;
145 std::cerr << std::flush;
146 fflush(stdout);
147 fflush(stderr);
148 EXPECT_GE(msg->entry.hdr_size, sizeof(logger_entry));
149
150 fprintf(stderr, "%s: [%u] ", prefix, msg->len());
151 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
152 fprintf(stderr, "pid=%u tid=%u %u.%09u ", msg->entry.pid, msg->entry.tid, msg->entry.sec,
153 msg->entry.nsec);
154 lid = msg->entry.lid;
155
156 switch (lid) {
157 case 0:
158 fprintf(stderr, "lid=main ");
159 break;
160 case 1:
161 fprintf(stderr, "lid=radio ");
162 break;
163 case 2:
164 fprintf(stderr, "lid=events ");
165 break;
166 case 3:
167 fprintf(stderr, "lid=system ");
168 break;
169 case 4:
170 fprintf(stderr, "lid=crash ");
171 break;
172 case 5:
173 fprintf(stderr, "lid=security ");
174 break;
175 case 6:
176 fprintf(stderr, "lid=kernel ");
177 break;
178 default:
179 if (lid >= 0) {
180 fprintf(stderr, "lid=%d ", lid);
181 }
182 }
183
184 unsigned int len = msg->entry.len;
185 fprintf(stderr, "msg[%u]={", len);
186 unsigned char* cp = reinterpret_cast<unsigned char*>(msg->msg());
187 if (!cp) {
188 static const unsigned char garbage[] = "<INVALID>";
189 cp = const_cast<unsigned char*>(garbage);
190 len = strlen(reinterpret_cast<const char*>(garbage));
191 }
192 while (len) {
193 unsigned char* p = cp;
194 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
195 ++p;
196 }
197 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
198 fprintf(stderr, "\"");
199 while (*cp) {
200 if (*cp != '\n') {
201 fprintf(stderr, "%c", *cp);
202 } else {
203 fprintf(stderr, "\\n");
204 }
205 ++cp;
206 --len;
207 }
208 fprintf(stderr, "\"");
209 } else {
210 fprintf(stderr, "%02x", *cp);
211 }
212 ++cp;
213 if (--len) {
214 fprintf(stderr, ", ");
215 }
216 }
217 fprintf(stderr, "}\n");
218 fflush(stderr);
219 }
220 #endif
221
222 // b/26447386 confirm fixed
timeout_negative(const char * command)223 void timeout_negative([[maybe_unused]] const char* command) {
224 #ifdef __ANDROID__
225 log_msg msg_wrap, msg_timeout;
226 bool content_wrap = false, content_timeout = false, written = false;
227 unsigned int alarm_wrap = 0, alarm_timeout = 0;
228 // A few tries to get it right just in case wrap kicks in due to
229 // content providers being active during the test.
230 int i = 3;
231
232 while (--i) {
233 unique_fd fd(
234 socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET));
235 ASSERT_LT(0, fd) << "Failed to open logdr: " << strerror(errno);
236
237 struct sigaction ignore = {.sa_handler = caught_signal};
238 sigemptyset(&ignore.sa_mask);
239 struct sigaction old_sigaction;
240 sigaction(SIGALRM, &ignore, &old_sigaction);
241 unsigned int old_alarm = alarm(3);
242
243 written = write_command(fd, command);
244 if (!written) {
245 alarm(old_alarm);
246 sigaction(SIGALRM, &old_sigaction, nullptr);
247 continue;
248 }
249
250 // alarm triggers at 50% of the --wrap time out
251 content_wrap = TEMP_FAILURE_RETRY(recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0)) > 0;
252
253 alarm_wrap = alarm(5);
254
255 // alarm triggers at 133% of the --wrap time out
256 content_timeout = TEMP_FAILURE_RETRY(recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0)) > 0;
257 if (!content_timeout) { // make sure we hit dumpAndClose
258 content_timeout =
259 TEMP_FAILURE_RETRY(recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0)) > 0;
260 }
261
262 if (old_alarm > 0) {
263 unsigned int time_spent = 3 - alarm_wrap;
264 if (old_alarm > time_spent + 1) {
265 old_alarm -= time_spent;
266 } else {
267 old_alarm = 2;
268 }
269 }
270 alarm_timeout = alarm(old_alarm);
271 sigaction(SIGALRM, &old_sigaction, nullptr);
272
273 if (content_wrap && alarm_wrap && content_timeout && alarm_timeout) {
274 break;
275 }
276 }
277
278 if (content_wrap) {
279 dump_log_msg("wrap", &msg_wrap, -1);
280 }
281
282 if (content_timeout) {
283 dump_log_msg("timeout", &msg_timeout, -1);
284 }
285
286 EXPECT_TRUE(written);
287 EXPECT_TRUE(content_wrap);
288 EXPECT_NE(0U, alarm_wrap);
289 EXPECT_TRUE(content_timeout);
290 EXPECT_NE(0U, alarm_timeout);
291 #else
292 command = nullptr;
293 GTEST_LOG_(INFO) << "This test does nothing.\n";
294 #endif
295 }
296
TEST(logd,timeout_no_start)297 TEST(logd, timeout_no_start) {
298 timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6");
299 }
300
TEST(logd,timeout_start_epoch)301 TEST(logd, timeout_start_epoch) {
302 timeout_negative(
303 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000");
304 }
305
306 #ifdef LOGD_ENABLE_FLAKY_TESTS
307 // b/26447386 refined behavior
TEST(logd,timeout)308 TEST(logd, timeout) {
309 #ifdef __ANDROID__
310 // b/33962045 This test interferes with other log reader tests that
311 // follow because of file descriptor socket persistence in the same
312 // process. So let's fork it to isolate it from giving us pain.
313
314 pid_t pid = fork();
315
316 if (pid) {
317 siginfo_t info = {};
318 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
319 ASSERT_EQ(0, info.si_status);
320 return;
321 }
322
323 log_msg msg_wrap, msg_timeout;
324 bool content_wrap = false, content_timeout = false, written = false;
325 unsigned int alarm_wrap = 0, alarm_timeout = 0;
326 // A few tries to get it right just in case wrap kicks in due to
327 // content providers being active during the test.
328 int i = 5;
329 log_time start(CLOCK_REALTIME);
330 start.tv_sec -= 30; // reach back a moderate period of time
331
332 while (--i) {
333 unique_fd fd(
334 socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET));
335 ASSERT_LT(0, fd) << "Failed to open logdr: " << strerror(errno);
336
337 std::string ask = android::base::StringPrintf(
338 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32
339 ".%09" PRIu32,
340 start.tv_sec, start.tv_nsec);
341
342 struct sigaction ignore = {.sa_handler = caught_signal};
343 sigemptyset(&ignore.sa_mask);
344 struct sigaction old_sigaction;
345 sigaction(SIGALRM, &ignore, &old_sigaction);
346 unsigned int old_alarm = alarm(3);
347
348 written = write_command(fd, ask);
349 if (!written) {
350 alarm(old_alarm);
351 sigaction(SIGALRM, &old_sigaction, nullptr);
352 continue;
353 }
354
355 // alarm triggers at 50% of the --wrap time out
356 content_wrap = TEMP_FAILURE_RETRY(recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0)) > 0;
357
358 alarm_wrap = alarm(5);
359
360 // alarm triggers at 133% of the --wrap time out
361 content_timeout = TEMP_FAILURE_RETRY(recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0)) > 0;
362 if (!content_timeout) { // make sure we hit dumpAndClose
363 content_timeout =
364 TEMP_FAILURE_RETRY(recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0)) > 0;
365 }
366
367 if (old_alarm > 0) {
368 unsigned int time_spent = 3 - alarm_wrap;
369 if (old_alarm > time_spent + 1) {
370 old_alarm -= time_spent;
371 } else {
372 old_alarm = 2;
373 }
374 }
375 alarm_timeout = alarm(old_alarm);
376 sigaction(SIGALRM, &old_sigaction, nullptr);
377
378 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) {
379 break;
380 }
381
382 // modify start time in case content providers are relatively
383 // active _or_ inactive during the test.
384 if (content_timeout) {
385 log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
386 if (msg < start) {
387 fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec,
388 msg_timeout.entry.nsec, (unsigned)start.tv_sec,
389 (unsigned)start.tv_nsec);
390 _exit(-1);
391 }
392 if (msg > start) {
393 start = msg;
394 start.tv_sec += 30;
395 log_time now = log_time(CLOCK_REALTIME);
396 if (start > now) {
397 start = now;
398 --start.tv_sec;
399 }
400 }
401 } else {
402 start.tv_sec -= 120; // inactive, reach further back!
403 }
404 }
405
406 if (content_wrap) {
407 dump_log_msg("wrap", &msg_wrap, -1);
408 }
409
410 if (content_timeout) {
411 dump_log_msg("timeout", &msg_timeout, -1);
412 }
413
414 if (content_wrap || !content_timeout) {
415 fprintf(stderr, "start=%" PRIu32 ".%09" PRIu32 "\n", start.tv_sec,
416 start.tv_nsec);
417 }
418
419 EXPECT_TRUE(written);
420 EXPECT_FALSE(content_wrap);
421 EXPECT_EQ(0U, alarm_wrap);
422 EXPECT_TRUE(content_timeout);
423 EXPECT_NE(0U, alarm_timeout);
424
425 _exit(!written + content_wrap + alarm_wrap + !content_timeout +
426 !alarm_timeout);
427 #else
428 GTEST_LOG_(INFO) << "This test does nothing.\n";
429 #endif
430 }
431 #endif
432
433 #ifdef LOGD_ENABLE_FLAKY_TESTS
434 // b/27242723 confirmed fixed
TEST(logd,SNDTIMEO)435 TEST(logd, SNDTIMEO) {
436 #ifdef __ANDROID__
437 static const unsigned sndtimeo =
438 LOGD_SNDTIMEO; // <sigh> it has to be done!
439 static const unsigned sleep_time = sndtimeo + 3;
440 static const unsigned alarm_time = sleep_time + 5;
441
442 unique_fd fd(socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET));
443 ASSERT_LT(0, fd) << "Failed to open logdr: " << strerror(errno);
444
445 struct sigaction ignore = {.sa_handler = caught_signal};
446 sigemptyset(&ignore.sa_mask);
447 struct sigaction old_sigaction;
448 sigaction(SIGALRM, &ignore, &old_sigaction);
449 unsigned int old_alarm = alarm(alarm_time);
450
451 // Stream all sources.
452 ASSERT_TRUE(write_command(fd, "stream lids=0,1,2,3,4,5,6"));
453
454 log_msg msg;
455 bool read_one = TEMP_FAILURE_RETRY(recv(fd, msg.buf, sizeof(msg), 0)) > 0;
456 EXPECT_TRUE(read_one);
457 if (read_one) {
458 dump_log_msg("user", &msg, -1);
459 }
460
461 fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo);
462 sleep(sleep_time);
463
464 // flush will block if we did not trigger. if it did, last entry returns 0
465 int recv_ret;
466 do {
467 recv_ret = TEMP_FAILURE_RETRY(recv(fd, msg.buf, sizeof(msg), 0));
468 } while (recv_ret > 0);
469 int save_errno = (recv_ret < 0) ? errno : 0;
470
471 EXPECT_NE(0U, alarm(old_alarm));
472 sigaction(SIGALRM, &old_sigaction, nullptr);
473
474 EXPECT_EQ(0, recv_ret);
475 if (recv_ret > 0) {
476 dump_log_msg("user", &msg, -1);
477 }
478 EXPECT_EQ(0, save_errno);
479 #else
480 GTEST_LOG_(INFO) << "This test does nothing.\n";
481 #endif
482 }
483 #endif
484
TEST(logd,getEventTag_list)485 TEST(logd, getEventTag_list) {
486 #ifdef __ANDROID__
487 std::string result;
488 send_to_control("getEventTag name=*", result);
489 ASSERT_FALSE(result.empty());
490
491 char* cp;
492 long ret = strtol(result.c_str(), &cp, 10);
493 EXPECT_GT(ret, 4096) << "Command result: " << result;
494 #else
495 GTEST_LOG_(INFO) << "This test does nothing.\n";
496 #endif
497 }
498
TEST(logd,getEventTag_42)499 TEST(logd, getEventTag_42) {
500 #ifdef __ANDROID__
501 std::string result;
502 send_to_control("getEventTag id=42", result);
503 ASSERT_FALSE(result.empty());
504
505 char* cp;
506 long ret = strtol(result.c_str(), &cp, 10);
507 EXPECT_GT(ret, 16) << "Command result: " << result;
508 EXPECT_NE(std::string::npos, result.find("\t(to life the universe etc|3)"))
509 << "Command result: " << result;
510 EXPECT_NE(std::string::npos, result.find("answer")) << "Command result: " << result;
511 #else
512 GTEST_LOG_(INFO) << "This test does nothing.\n";
513 #endif
514 }
515
TEST(logd,getEventTag_newentry)516 TEST(logd, getEventTag_newentry) {
517 #ifdef __ANDROID__
518 log_time now(CLOCK_MONOTONIC);
519 std::string name;
520 name = android::base::StringPrintf("a%" PRIu64, now.nsec());
521
522 std::string command;
523 command = android::base::StringPrintf("getEventTag name=%s format=\"(new|1)\"", name.c_str());
524
525 std::string result;
526 send_to_control(command.c_str(), result);
527 ASSERT_FALSE(result.empty());
528
529 char* cp;
530 long ret = strtol(result.c_str(), &cp, 10);
531 EXPECT_GT(ret, 16) << "Command result: " << result;
532 EXPECT_NE(std::string::npos, result.find("\t(new|1)")) << "Command result: " << result;
533 EXPECT_NE(std::string::npos, result.find(name)) << "Command result: " << result;
534 // ToDo: also look for this in /data/misc/logd/event-log-tags and
535 // /dev/event-log-tags.
536 #else
537 GTEST_LOG_(INFO) << "This test does nothing.\n";
538 #endif
539 }
540
TEST(logd,no_epipe)541 TEST(logd, no_epipe) {
542 #ifdef __ANDROID__
543 // Actually generating SIGPIPE in logd is racy, since we need to close the socket quicker than
544 // logd finishes writing the data to it, so we try 5 times, which should be enough to trigger
545 // SIGPIPE if logd isn't ignoring SIGPIPE
546 for (int i = 0; i < 5; ++i) {
547 unique_fd sock1(
548 socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM));
549 ASSERT_LT(0, sock1) << "Failed to open logd: " << strerror(errno);
550 unique_fd sock2(
551 socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM));
552 ASSERT_LT(0, sock2) << "Failed to open logd: " << strerror(errno);
553
554 std::string message = "getStatistics 0 1 2 3 4 5 6 7";
555 ASSERT_TRUE(write_command(sock1, message));
556 sock1.reset();
557 ASSERT_TRUE(write_command(sock2, message));
558
559 struct pollfd p = {.fd = sock2, .events = POLLIN, .revents = 0};
560
561 int ret = TEMP_FAILURE_RETRY(poll(&p, 1, 1000));
562 EXPECT_EQ(ret, 1);
563 EXPECT_TRUE(p.revents & POLLIN);
564 EXPECT_FALSE(p.revents & POLL_ERR);
565 }
566 #else
567 GTEST_LOG_(INFO) << "This test does nothing.\n";
568 #endif
569 }
570
571 // Only AID_ROOT, AID_SYSTEM, and AID_LOG can set log sizes. Ensure that a different user, AID_BIN,
572 // cannot set the log size.
TEST(logd,logging_permissions)573 TEST(logd, logging_permissions) {
574 #ifdef __ANDROID__
575 if (getuid() != 0) {
576 GTEST_SKIP() << "This test requires root";
577 }
578
579 auto child_main = [] {
580 setgroups(0, nullptr);
581 setgid(AID_BIN);
582 setuid(AID_BIN);
583
584 std::unique_ptr<logger_list, decltype(&android_logger_list_free)> logger_list{
585 android_logger_list_alloc(0, 0, 0), &android_logger_list_free};
586 if (!logger_list) {
587 _exit(1);
588 }
589 auto logger = android_logger_open(logger_list.get(), LOG_ID_MAIN);
590 if (!logger) {
591 _exit(2);
592 }
593 // This line should fail, so if it returns 0, we exit with an error.
594 if (android_logger_set_log_size(logger, 2 * 1024 * 1024) == 0) {
595 _exit(3);
596 }
597 _exit(EXIT_SUCCESS);
598 };
599
600 ASSERT_EXIT(child_main(), testing::ExitedWithCode(0), "");
601 #else
602 GTEST_LOG_(INFO) << "This test does nothing.\n";
603 #endif
604 }
605