/* * Copyright (C) 2020 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include "LogBufferTest.h" #include #include #include #include #include #include #include #include "LogReaderThread.h" #include "LogWriter.h" using android::base::Join; using android::base::Split; using android::base::StringPrintf; #ifndef __ANDROID__ unsigned long __android_logger_get_buffer_size(log_id_t) { return 1024 * 1024; } bool __android_logger_valid_buffer_size(unsigned long) { return true; } #endif void android::prdebug(const char* fmt, ...) { va_list ap; va_start(ap, fmt); vfprintf(stderr, fmt, ap); fprintf(stderr, "\n"); va_end(ap); } char* android::uidToName(uid_t) { return nullptr; } static std::vector CompareLoggerEntries(const logger_entry& expected, const logger_entry& result, bool ignore_len) { std::vector errors; if (!ignore_len && expected.len != result.len) { errors.emplace_back( StringPrintf("len: expected %" PRIu16 " vs %" PRIu16, expected.len, result.len)); } if (expected.hdr_size != result.hdr_size) { errors.emplace_back(StringPrintf("hdr_size: %" PRIu16 " vs %" PRIu16, expected.hdr_size, result.hdr_size)); } if (expected.pid != result.pid) { errors.emplace_back( StringPrintf("pid: expected %" PRIi32 " vs %" PRIi32, expected.pid, result.pid)); } if (expected.tid != result.tid) { errors.emplace_back( StringPrintf("tid: expected %" PRIu32 " vs %" PRIu32, expected.tid, result.tid)); } if (expected.sec != result.sec) { errors.emplace_back( StringPrintf("sec: expected %" PRIu32 " vs %" PRIu32, expected.sec, result.sec)); } if (expected.nsec != result.nsec) { errors.emplace_back( StringPrintf("nsec: expected %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec)); } if (expected.lid != result.lid) { errors.emplace_back( StringPrintf("lid: expected %" PRIu32 " vs %" PRIu32, expected.lid, result.lid)); } if (expected.uid != result.uid) { errors.emplace_back( StringPrintf("uid: expected %" PRIu32 " vs %" PRIu32, expected.uid, result.uid)); } return errors; } static std::string MakePrintable(std::string in) { if (in.size() > 80) { in = in.substr(0, 80) + "..."; } std::string result; for (const char c : in) { if (isprint(c)) { result.push_back(c); } else { result.append(StringPrintf("\\%02x", static_cast(c) & 0xFF)); } } return result; } static std::string CompareMessages(const std::string& expected, const std::string& result) { if (expected == result) { return {}; } size_t diff_index = 0; for (; diff_index < std::min(expected.size(), result.size()); ++diff_index) { if (expected[diff_index] != result[diff_index]) { break; } } if (diff_index < 10) { auto expected_short = MakePrintable(expected); auto result_short = MakePrintable(result); return StringPrintf("msg: expected '%s' vs '%s'", expected_short.c_str(), result_short.c_str()); } auto expected_short = MakePrintable(expected.substr(diff_index)); auto result_short = MakePrintable(result.substr(diff_index)); return StringPrintf("msg: index %zu: expected '%s' vs '%s'", diff_index, expected_short.c_str(), result_short.c_str()); } static std::string CompareRegexMessages(const std::string& expected, const std::string& result) { auto expected_pieces = Split(expected, std::string("\0", 1)); auto result_pieces = Split(result, std::string("\0", 1)); if (expected_pieces.size() != 3 || result_pieces.size() != 3) { return StringPrintf( "msg: should have 3 null delimited strings found %d in expected, %d in result: " "'%s' vs '%s'", static_cast(expected_pieces.size()), static_cast(result_pieces.size()), MakePrintable(expected).c_str(), MakePrintable(result).c_str()); } if (expected_pieces[0] != result_pieces[0]) { return StringPrintf("msg: tag/priority mismatch expected '%s' vs '%s'", MakePrintable(expected_pieces[0]).c_str(), MakePrintable(result_pieces[0]).c_str()); } std::regex expected_tag_regex(expected_pieces[1]); if (!std::regex_search(result_pieces[1], expected_tag_regex)) { return StringPrintf("msg: message regex mismatch expected '%s' vs '%s'", MakePrintable(expected_pieces[1]).c_str(), MakePrintable(result_pieces[1]).c_str()); } if (expected_pieces[2] != result_pieces[2]) { return StringPrintf("msg: nothing expected after final null character '%s' vs '%s'", MakePrintable(expected_pieces[2]).c_str(), MakePrintable(result_pieces[2]).c_str()); } return {}; } void CompareLogMessages(const std::vector& expected, const std::vector& result) { EXPECT_EQ(expected.size(), result.size()); size_t end = std::min(expected.size(), result.size()); size_t num_errors = 0; for (size_t i = 0; i < end; ++i) { auto errors = CompareLoggerEntries(expected[i].entry, result[i].entry, expected[i].regex_compare); auto msg_error = expected[i].regex_compare ? CompareRegexMessages(expected[i].message, result[i].message) : CompareMessages(expected[i].message, result[i].message); if (!msg_error.empty()) { errors.emplace_back(msg_error); } if (!errors.empty()) { GTEST_LOG_(ERROR) << "Mismatch log message " << i << "\n" << Join(errors, "\n"); ++num_errors; } } EXPECT_EQ(0U, num_errors); } void FixupMessages(std::vector* messages) { for (auto& [entry, message, _] : *messages) { entry.hdr_size = sizeof(logger_entry); entry.len = message.size(); } } TEST_P(LogBufferTest, smoke) { std::vector log_messages = { {{ .pid = 1, .tid = 1, .sec = 1234, .nsec = 323001, .lid = LOG_ID_MAIN, .uid = 0, }, "smoke test"}, }; FixupMessages(&log_messages); LogMessages(log_messages); std::vector read_log_messages; std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); uint64_t flush_result = log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); EXPECT_EQ(1ULL, flush_result); CompareLogMessages(log_messages, read_log_messages); } TEST_P(LogBufferTest, smoke_with_reader_thread) { std::vector log_messages = { {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0}, "first"}, {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0}, "second"}, {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_KERNEL, .uid = 0}, "third"}, {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20004, .lid = LOG_ID_MAIN, .uid = 0}, "fourth"}, {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20005, .lid = LOG_ID_RADIO, .uid = 0}, "fifth"}, {{.pid = 2, .tid = 2, .sec = 10000, .nsec = 20006, .lid = LOG_ID_RADIO, .uid = 0}, "sixth"}, {{.pid = 3, .tid = 2, .sec = 10000, .nsec = 20007, .lid = LOG_ID_RADIO, .uid = 0}, "seventh"}, {{.pid = 4, .tid = 2, .sec = 10000, .nsec = 20008, .lid = LOG_ID_MAIN, .uid = 0}, "eighth"}, {{.pid = 5, .tid = 2, .sec = 10000, .nsec = 20009, .lid = LOG_ID_CRASH, .uid = 0}, "nineth"}, {{.pid = 6, .tid = 2, .sec = 10000, .nsec = 20011, .lid = LOG_ID_MAIN, .uid = 0}, "tenth"}, }; FixupMessages(&log_messages); LogMessages(log_messages); std::vector read_log_messages; bool released = false; { auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; std::unique_ptr test_writer(new TestWriter(&read_log_messages, &released)); std::unique_ptr log_reader( new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true, 0, ~0, 0, {}, 1, {})); reader_list_.reader_threads().emplace_back(std::move(log_reader)); } while (!released) { usleep(5000); } { auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; EXPECT_EQ(0U, reader_list_.reader_threads().size()); } CompareLogMessages(log_messages, read_log_messages); } // Generate random messages, set the 'sec' parameter explicit though, to be able to track the // expected order of messages. LogMessage GenerateRandomLogMessage(uint32_t sec) { auto rand_uint32 = [](int max) -> uint32_t { return rand() % max; }; logger_entry entry = { .hdr_size = sizeof(logger_entry), .pid = rand() % 5000, .tid = rand_uint32(5000), .sec = sec, .nsec = rand_uint32(NS_PER_SEC), .lid = rand_uint32(LOG_ID_STATS), .uid = rand_uint32(100000), }; // See comment in ChattyLogBuffer::Log() for why this is disallowed. if (entry.nsec % 1000 == 0) { ++entry.nsec; } if (entry.lid == LOG_ID_EVENTS) { entry.lid = LOG_ID_KERNEL; } std::string message; char priority = ANDROID_LOG_INFO + rand() % 2; message.push_back(priority); int tag_length = 2 + rand() % 10; for (int i = 0; i < tag_length; ++i) { message.push_back('a' + rand() % 26); } message.push_back('\0'); int msg_length = 2 + rand() % 1000; for (int i = 0; i < msg_length; ++i) { message.push_back('a' + rand() % 26); } message.push_back('\0'); entry.len = message.size(); return {entry, message}; } TEST_P(LogBufferTest, random_messages) { srand(1); std::vector log_messages; for (size_t i = 0; i < 1000; ++i) { log_messages.emplace_back(GenerateRandomLogMessage(i)); } LogMessages(log_messages); std::vector read_log_messages; bool released = false; { auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; std::unique_ptr test_writer(new TestWriter(&read_log_messages, &released)); std::unique_ptr log_reader( new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true, 0, ~0, 0, {}, 1, {})); reader_list_.reader_threads().emplace_back(std::move(log_reader)); } while (!released) { usleep(5000); } { auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; EXPECT_EQ(0U, reader_list_.reader_threads().size()); } CompareLogMessages(log_messages, read_log_messages); } INSTANTIATE_TEST_CASE_P(LogBufferTests, LogBufferTest, testing::Values("chatty", "simple"));