1 /*
2 * Copyright (C) 2020 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 "LogBufferTest.h"
18
19 #include <unistd.h>
20
21 #include <limits>
22 #include <memory>
23 #include <regex>
24 #include <vector>
25
26 #include <android-base/stringprintf.h>
27 #include <android-base/strings.h>
28
29 #include "LogBuffer.h"
30 #include "LogReaderThread.h"
31 #include "LogWriter.h"
32
33 using android::base::Join;
34 using android::base::Split;
35 using android::base::StringPrintf;
36
uidToName(uid_t)37 char* android::uidToName(uid_t) {
38 return nullptr;
39 }
40
CompareLoggerEntries(const logger_entry & expected,const logger_entry & result,bool ignore_len)41 static std::vector<std::string> CompareLoggerEntries(const logger_entry& expected,
42 const logger_entry& result, bool ignore_len) {
43 std::vector<std::string> errors;
44 if (!ignore_len && expected.len != result.len) {
45 errors.emplace_back(
46 StringPrintf("len: expected %" PRIu16 " vs %" PRIu16, expected.len, result.len));
47 }
48 if (expected.hdr_size != result.hdr_size) {
49 errors.emplace_back(StringPrintf("hdr_size: %" PRIu16 " vs %" PRIu16, expected.hdr_size,
50 result.hdr_size));
51 }
52 if (expected.pid != result.pid) {
53 errors.emplace_back(
54 StringPrintf("pid: expected %" PRIi32 " vs %" PRIi32, expected.pid, result.pid));
55 }
56 if (expected.tid != result.tid) {
57 errors.emplace_back(
58 StringPrintf("tid: expected %" PRIu32 " vs %" PRIu32, expected.tid, result.tid));
59 }
60 if (expected.sec != result.sec) {
61 errors.emplace_back(
62 StringPrintf("sec: expected %" PRIu32 " vs %" PRIu32, expected.sec, result.sec));
63 }
64 if (expected.nsec != result.nsec) {
65 errors.emplace_back(
66 StringPrintf("nsec: expected %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec));
67 }
68 if (expected.lid != result.lid) {
69 errors.emplace_back(
70 StringPrintf("lid: expected %" PRIu32 " vs %" PRIu32, expected.lid, result.lid));
71 }
72 if (expected.uid != result.uid) {
73 errors.emplace_back(
74 StringPrintf("uid: expected %" PRIu32 " vs %" PRIu32, expected.uid, result.uid));
75 }
76 return errors;
77 }
78
MakePrintable(std::string in)79 static std::string MakePrintable(std::string in) {
80 if (in.size() > 80) {
81 in = in.substr(0, 80) + "...";
82 }
83 std::string result;
84 for (const char c : in) {
85 if (isprint(c)) {
86 result.push_back(c);
87 } else {
88 result.append(StringPrintf("\\%02x", static_cast<int>(c) & 0xFF));
89 }
90 }
91 return result;
92 }
93
CompareMessages(const std::string & expected,const std::string & result)94 static std::string CompareMessages(const std::string& expected, const std::string& result) {
95 if (expected == result) {
96 return {};
97 }
98 size_t diff_index = 0;
99 for (; diff_index < std::min(expected.size(), result.size()); ++diff_index) {
100 if (expected[diff_index] != result[diff_index]) {
101 break;
102 }
103 }
104
105 if (diff_index < 80) {
106 auto expected_short = MakePrintable(expected);
107 auto result_short = MakePrintable(result);
108 return StringPrintf("msg: expected '%s' vs '%s'", expected_short.c_str(),
109 result_short.c_str());
110 }
111
112 auto expected_short = MakePrintable(expected.substr(diff_index));
113 auto result_short = MakePrintable(result.substr(diff_index));
114 return StringPrintf("msg: index %zu: expected '%s' vs '%s'", diff_index, expected_short.c_str(),
115 result_short.c_str());
116 }
117
CompareRegexMessages(const std::string & expected,const std::string & result)118 static std::string CompareRegexMessages(const std::string& expected, const std::string& result) {
119 auto expected_pieces = Split(expected, std::string("\0", 1));
120 auto result_pieces = Split(result, std::string("\0", 1));
121
122 if (expected_pieces.size() != 3 || result_pieces.size() != 3) {
123 return StringPrintf(
124 "msg: should have 3 null delimited strings found %d in expected, %d in result: "
125 "'%s' vs '%s'",
126 static_cast<int>(expected_pieces.size()), static_cast<int>(result_pieces.size()),
127 MakePrintable(expected).c_str(), MakePrintable(result).c_str());
128 }
129 if (expected_pieces[0] != result_pieces[0]) {
130 return StringPrintf("msg: tag/priority mismatch expected '%s' vs '%s'",
131 MakePrintable(expected_pieces[0]).c_str(),
132 MakePrintable(result_pieces[0]).c_str());
133 }
134 std::regex expected_tag_regex(expected_pieces[1]);
135 if (!std::regex_search(result_pieces[1], expected_tag_regex)) {
136 return StringPrintf("msg: message regex mismatch expected '%s' vs '%s'",
137 MakePrintable(expected_pieces[1]).c_str(),
138 MakePrintable(result_pieces[1]).c_str());
139 }
140 if (expected_pieces[2] != result_pieces[2]) {
141 return StringPrintf("msg: nothing expected after final null character '%s' vs '%s'",
142 MakePrintable(expected_pieces[2]).c_str(),
143 MakePrintable(result_pieces[2]).c_str());
144 }
145 return {};
146 }
147
CompareLogMessages(const std::vector<LogMessage> & expected,const std::vector<LogMessage> & result)148 void CompareLogMessages(const std::vector<LogMessage>& expected,
149 const std::vector<LogMessage>& result) {
150 EXPECT_EQ(expected.size(), result.size());
151 size_t end = std::min(expected.size(), result.size());
152 size_t num_errors = 0;
153 for (size_t i = 0; i < end; ++i) {
154 auto errors =
155 CompareLoggerEntries(expected[i].entry, result[i].entry, expected[i].regex_compare);
156 auto msg_error = expected[i].regex_compare
157 ? CompareRegexMessages(expected[i].message, result[i].message)
158 : CompareMessages(expected[i].message, result[i].message);
159 if (!msg_error.empty()) {
160 errors.emplace_back(msg_error);
161 }
162 if (!errors.empty()) {
163 GTEST_LOG_(ERROR) << "Mismatch log message " << i << "\n" << Join(errors, "\n");
164 ++num_errors;
165 }
166 }
167 EXPECT_EQ(0U, num_errors);
168 }
169
FixupMessages(std::vector<LogMessage> * messages)170 void FixupMessages(std::vector<LogMessage>* messages) {
171 for (auto& [entry, message, _] : *messages) {
172 entry.hdr_size = sizeof(logger_entry);
173 entry.len = message.size();
174 }
175 }
176
TEST_P(LogBufferTest,smoke)177 TEST_P(LogBufferTest, smoke) {
178 std::vector<LogMessage> log_messages = {
179 {{
180 .pid = 1,
181 .tid = 1,
182 .sec = 1234,
183 .nsec = 323001,
184 .lid = LOG_ID_MAIN,
185 .uid = 0,
186 },
187 "smoke test"},
188 };
189 FixupMessages(&log_messages);
190 LogMessages(log_messages);
191
192 auto flush_result = FlushMessages();
193 EXPECT_EQ(2ULL, flush_result.next_sequence);
194 CompareLogMessages(log_messages, flush_result.messages);
195 }
196
TEST_P(LogBufferTest,smoke_with_reader_thread)197 TEST_P(LogBufferTest, smoke_with_reader_thread) {
198 std::vector<LogMessage> log_messages = {
199 {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
200 "first"},
201 {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
202 "second"},
203 {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_KERNEL, .uid = 0},
204 "third"},
205 {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20004, .lid = LOG_ID_MAIN, .uid = 0},
206 "fourth"},
207 {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20005, .lid = LOG_ID_RADIO, .uid = 0},
208 "fifth"},
209 {{.pid = 2, .tid = 2, .sec = 10000, .nsec = 20006, .lid = LOG_ID_RADIO, .uid = 0},
210 "sixth"},
211 {{.pid = 3, .tid = 2, .sec = 10000, .nsec = 20007, .lid = LOG_ID_RADIO, .uid = 0},
212 "seventh"},
213 {{.pid = 4, .tid = 2, .sec = 10000, .nsec = 20008, .lid = LOG_ID_MAIN, .uid = 0},
214 "eighth"},
215 {{.pid = 5, .tid = 2, .sec = 10000, .nsec = 20009, .lid = LOG_ID_CRASH, .uid = 0},
216 "nineth"},
217 {{.pid = 6, .tid = 2, .sec = 10000, .nsec = 20011, .lid = LOG_ID_MAIN, .uid = 0},
218 "tenth"},
219 };
220 FixupMessages(&log_messages);
221 LogMessages(log_messages);
222
223 auto read_log_messages = ReadLogMessagesNonBlockingThread({});
224 CompareLogMessages(log_messages, read_log_messages);
225 }
226
227 // Generate random messages, set the 'sec' parameter explicit though, to be able to track the
228 // expected order of messages.
GenerateRandomLogMessage(uint32_t sec)229 LogMessage GenerateRandomLogMessage(uint32_t sec) {
230 auto rand_uint32 = [](int max) -> uint32_t { return rand() % max; };
231 logger_entry entry = {
232 .hdr_size = sizeof(logger_entry),
233 .pid = rand() % 5000,
234 .tid = rand_uint32(5000),
235 .sec = sec,
236 .nsec = rand_uint32(NS_PER_SEC),
237 .lid = rand_uint32(LOG_ID_STATS),
238 .uid = rand_uint32(100000),
239 };
240
241 // See comment in ChattyLogBuffer::Log() for why this is disallowed.
242 if (entry.nsec % 1000 == 0) {
243 ++entry.nsec;
244 }
245
246 if (entry.lid == LOG_ID_EVENTS) {
247 entry.lid = LOG_ID_KERNEL;
248 }
249
250 std::string message;
251 char priority = ANDROID_LOG_INFO + rand() % 2;
252 message.push_back(priority);
253
254 int tag_length = 2 + rand() % 10;
255 for (int i = 0; i < tag_length; ++i) {
256 message.push_back('a' + rand() % 26);
257 }
258 message.push_back('\0');
259
260 int msg_length = 2 + rand() % 1000;
261 for (int i = 0; i < msg_length; ++i) {
262 message.push_back('a' + rand() % 26);
263 }
264 message.push_back('\0');
265
266 entry.len = message.size();
267
268 return {entry, message};
269 }
270
GenerateRandomLogMessages(size_t count)271 std::vector<LogMessage> GenerateRandomLogMessages(size_t count) {
272 srand(1);
273 std::vector<LogMessage> log_messages;
274 for (size_t i = 0; i < count; ++i) {
275 log_messages.emplace_back(GenerateRandomLogMessage(i));
276 }
277 return log_messages;
278 }
279
TEST_P(LogBufferTest,random_messages)280 TEST_P(LogBufferTest, random_messages) {
281 auto log_messages = GenerateRandomLogMessages(1000);
282 LogMessages(log_messages);
283
284 auto read_log_messages = ReadLogMessagesNonBlockingThread({});
285 CompareLogMessages(log_messages, read_log_messages);
286 }
287
TEST_P(LogBufferTest,read_last_sequence)288 TEST_P(LogBufferTest, read_last_sequence) {
289 std::vector<LogMessage> log_messages = {
290 {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
291 "first"},
292 {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
293 "second"},
294 {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
295 "third"},
296 };
297 FixupMessages(&log_messages);
298 LogMessages(log_messages);
299
300 std::vector<LogMessage> expected_log_messages = {log_messages.back()};
301 auto read_log_messages = ReadLogMessagesNonBlockingThread({.sequence = 3});
302 CompareLogMessages(expected_log_messages, read_log_messages);
303 }
304
TEST_P(LogBufferTest,clear_logs)305 TEST_P(LogBufferTest, clear_logs) {
306 // Log 3 initial logs.
307 std::vector<LogMessage> log_messages = {
308 {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
309 "first"},
310 {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
311 "second"},
312 {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
313 "third"},
314 };
315 FixupMessages(&log_messages);
316 LogMessages(log_messages);
317
318 // Connect a blocking reader.
319 auto blocking_reader = TestReaderThread({.non_block = false}, *this);
320
321 // Wait up to 250ms for the reader to read the first 3 logs.
322 constexpr int kMaxRetryCount = 50;
323 int count = 0;
324 for (; count < kMaxRetryCount; ++count) {
325 usleep(5000);
326 auto lock = std::lock_guard{logd_lock};
327 if (reader_list_.reader_threads().back()->start() == 4) {
328 break;
329 }
330 }
331 ASSERT_LT(count, kMaxRetryCount);
332
333 // Clear the log buffer.
334 log_buffer_->Clear(LOG_ID_MAIN, 0);
335
336 // Log 3 more logs.
337 std::vector<LogMessage> after_clear_messages = {
338 {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0},
339 "4th"},
340 {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0},
341 "5th"},
342 {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0},
343 "6th"},
344 };
345 FixupMessages(&after_clear_messages);
346 LogMessages(after_clear_messages);
347
348 // Wait up to 250ms for the reader to read the 3 additional logs.
349 for (count = 0; count < kMaxRetryCount; ++count) {
350 usleep(5000);
351 auto lock = std::lock_guard{logd_lock};
352 if (reader_list_.reader_threads().back()->start() == 7) {
353 break;
354 }
355 }
356 ASSERT_LT(count, kMaxRetryCount);
357
358 ReleaseAndJoinReaders();
359
360 // Check that we have read all 6 messages.
361 std::vector<LogMessage> expected_log_messages = log_messages;
362 expected_log_messages.insert(expected_log_messages.end(), after_clear_messages.begin(),
363 after_clear_messages.end());
364 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
365
366 // Finally, Flush messages and ensure that only the 3 logs after the clear remain in the buffer.
367 auto flush_after_clear_result = FlushMessages();
368 EXPECT_EQ(7ULL, flush_after_clear_result.next_sequence);
369 CompareLogMessages(after_clear_messages, flush_after_clear_result.messages);
370 }
371
TEST_P(LogBufferTest,tail100_nonblocking_1000total)372 TEST_P(LogBufferTest, tail100_nonblocking_1000total) {
373 auto log_messages = GenerateRandomLogMessages(1000);
374 LogMessages(log_messages);
375
376 constexpr int kTailCount = 100;
377 std::vector<LogMessage> expected_log_messages{log_messages.end() - kTailCount,
378 log_messages.end()};
379 auto read_log_messages = ReadLogMessagesNonBlockingThread({.tail = kTailCount});
380 CompareLogMessages(expected_log_messages, read_log_messages);
381 }
382
TEST_P(LogBufferTest,tail100_blocking_1000total_then1000more)383 TEST_P(LogBufferTest, tail100_blocking_1000total_then1000more) {
384 auto log_messages = GenerateRandomLogMessages(1000);
385 LogMessages(log_messages);
386
387 constexpr int kTailCount = 100;
388 auto blocking_reader = TestReaderThread({.non_block = false, .tail = kTailCount}, *this);
389
390 std::vector<LogMessage> expected_log_messages{log_messages.end() - kTailCount,
391 log_messages.end()};
392
393 // Wait for the reader to have read the messages.
394 int retry_count = 1s / 5000us;
395 while (retry_count--) {
396 usleep(5000);
397 auto lock = std::lock_guard{logd_lock};
398 if (blocking_reader.read_log_messages().size() == expected_log_messages.size()) {
399 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
400 break;
401 }
402 }
403 ASSERT_GT(retry_count, 0);
404
405 // Log more messages
406 log_messages = GenerateRandomLogMessages(1000);
407 LogMessages(log_messages);
408 expected_log_messages.insert(expected_log_messages.end(), log_messages.begin(),
409 log_messages.end());
410
411 // Wait for the reader to have read the new messages.
412 retry_count = 1s / 5000us;
413 while (retry_count--) {
414 usleep(5000);
415 auto lock = std::lock_guard{logd_lock};
416 if (blocking_reader.read_log_messages().size() == expected_log_messages.size()) {
417 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
418 break;
419 }
420 }
421 ASSERT_GT(retry_count, 0);
422
423 ReleaseAndJoinReaders();
424
425 // Final check that no extraneous logs were logged.
426 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
427 }
428
TEST_P(LogBufferTest,tail100_nonblocking_50total)429 TEST_P(LogBufferTest, tail100_nonblocking_50total) {
430 auto log_messages = GenerateRandomLogMessages(50);
431 LogMessages(log_messages);
432
433 constexpr int kTailCount = 100;
434 auto read_log_messages = ReadLogMessagesNonBlockingThread({.tail = kTailCount});
435 CompareLogMessages(log_messages, read_log_messages);
436 }
437
TEST_P(LogBufferTest,tail100_blocking_50total_then1000more)438 TEST_P(LogBufferTest, tail100_blocking_50total_then1000more) {
439 auto log_messages = GenerateRandomLogMessages(50);
440 LogMessages(log_messages);
441
442 constexpr int kTailCount = 100;
443 auto blocking_reader = TestReaderThread({.non_block = false, .tail = kTailCount}, *this);
444
445 std::vector<LogMessage> expected_log_messages = log_messages;
446
447 // Wait for the reader to have read the messages.
448 int retry_count = 1s / 5000us;
449 while (retry_count--) {
450 usleep(5000);
451 auto lock = std::lock_guard{logd_lock};
452 if (blocking_reader.read_log_messages().size() == expected_log_messages.size()) {
453 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
454 break;
455 }
456 }
457 ASSERT_GT(retry_count, 0);
458
459 // Log more messages
460 log_messages = GenerateRandomLogMessages(1000);
461 LogMessages(log_messages);
462 expected_log_messages.insert(expected_log_messages.end(), log_messages.begin(),
463 log_messages.end());
464
465 // Wait for the reader to have read the new messages.
466 retry_count = 1s / 5000us;
467 while (retry_count--) {
468 usleep(5000);
469 auto lock = std::lock_guard{logd_lock};
470 if (blocking_reader.read_log_messages().size() == expected_log_messages.size()) {
471 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
472
473 break;
474 }
475 }
476 ASSERT_GT(retry_count, 0);
477
478 ReleaseAndJoinReaders();
479
480 // Final check that no extraneous logs were logged.
481 CompareLogMessages(expected_log_messages, blocking_reader.read_log_messages());
482 }
483
484 INSTANTIATE_TEST_CASE_P(LogBufferTests, LogBufferTest,
485 testing::Values("chatty", "serialized", "simple"));
486