diff options
Diffstat (limited to 'logd/LogBufferTest.cpp')
| -rw-r--r-- | logd/LogBufferTest.cpp | 449 |
1 files changed, 449 insertions, 0 deletions
diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp new file mode 100644 index 0000000000..191110522e --- /dev/null +++ b/logd/LogBufferTest.cpp @@ -0,0 +1,449 @@ +/* + * 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 <unistd.h> + +#include <limits> +#include <memory> +#include <regex> +#include <vector> + +#include <android-base/stringprintf.h> +#include <android-base/strings.h> + +#include "LogBuffer.h" +#include "LogReaderThread.h" +#include "LogWriter.h" + +using android::base::Join; +using android::base::Split; +using android::base::StringPrintf; + +char* android::uidToName(uid_t) { + return nullptr; +} + +static std::vector<std::string> CompareLoggerEntries(const logger_entry& expected, + const logger_entry& result, bool ignore_len) { + std::vector<std::string> 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<int>(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 < 80) { + 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<int>(expected_pieces.size()), static_cast<int>(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<LogMessage>& expected, + const std::vector<LogMessage>& 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<LogMessage>* messages) { + for (auto& [entry, message, _] : *messages) { + entry.hdr_size = sizeof(logger_entry); + entry.len = message.size(); + } +} + +TEST_P(LogBufferTest, smoke) { + std::vector<LogMessage> 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<LogMessage> read_log_messages; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr)); + std::unique_ptr<FlushToState> flush_to_state = log_buffer_->CreateFlushToState(1, kLogMaskAll); + EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr)); + EXPECT_EQ(2ULL, flush_to_state->start()); + CompareLogMessages(log_messages, read_log_messages); +} + +TEST_P(LogBufferTest, smoke_with_reader_thread) { + std::vector<LogMessage> 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<LogMessage> read_log_messages; + bool released = false; + + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr<LogReaderThread> log_reader( + new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true, + 0, kLogMaskAll, 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<LogMessage> log_messages; + for (size_t i = 0; i < 1000; ++i) { + log_messages.emplace_back(GenerateRandomLogMessage(i)); + } + LogMessages(log_messages); + + std::vector<LogMessage> read_log_messages; + bool released = false; + + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr<LogReaderThread> log_reader( + new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true, + 0, kLogMaskAll, 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); +} + +TEST_P(LogBufferTest, read_last_sequence) { + std::vector<LogMessage> 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_MAIN, .uid = 0}, + "third"}, + }; + FixupMessages(&log_messages); + LogMessages(log_messages); + + std::vector<LogMessage> read_log_messages; + bool released = false; + + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr<LogReaderThread> log_reader( + new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true, + 0, kLogMaskAll, 0, {}, 3, {})); + 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()); + } + std::vector<LogMessage> expected_log_messages = {log_messages.back()}; + CompareLogMessages(expected_log_messages, read_log_messages); +} + +TEST_P(LogBufferTest, clear_logs) { + // Log 3 initial logs. + std::vector<LogMessage> 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_MAIN, .uid = 0}, + "third"}, + }; + FixupMessages(&log_messages); + LogMessages(log_messages); + + std::vector<LogMessage> read_log_messages; + bool released = false; + + // Connect a blocking reader. + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr<LogReaderThread> log_reader( + new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), false, + 0, kLogMaskAll, 0, {}, 1, {})); + reader_list_.reader_threads().emplace_back(std::move(log_reader)); + } + + // Wait up to 250ms for the reader to read the first 3 logs. + constexpr int kMaxRetryCount = 50; + int count = 0; + for (; count < kMaxRetryCount; ++count) { + usleep(5000); + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + if (reader_list_.reader_threads().back()->start() == 4) { + break; + } + } + ASSERT_LT(count, kMaxRetryCount); + + // Clear the log buffer. + log_buffer_->Clear(LOG_ID_MAIN, 0); + + // Log 3 more logs. + std::vector<LogMessage> after_clear_messages = { + {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0}, + "4th"}, + {{.pid = 10, .tid = 2, .sec = 10000, .nsec = 20002, .lid = LOG_ID_MAIN, .uid = 0}, + "5th"}, + {{.pid = 100, .tid = 2, .sec = 10000, .nsec = 20003, .lid = LOG_ID_MAIN, .uid = 0}, + "6th"}, + }; + FixupMessages(&after_clear_messages); + LogMessages(after_clear_messages); + + // Wait up to 250ms for the reader to read the 3 additional logs. + for (count = 0; count < kMaxRetryCount; ++count) { + usleep(5000); + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + if (reader_list_.reader_threads().back()->start() == 7) { + break; + } + } + ASSERT_LT(count, kMaxRetryCount); + + // Release the reader, wait for it to get the signal then check that it has been deleted. + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + reader_list_.reader_threads().back()->release_Locked(); + } + while (!released) { + usleep(5000); + } + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + EXPECT_EQ(0U, reader_list_.reader_threads().size()); + } + + // Check that we have read all 6 messages. + std::vector<LogMessage> expected_log_messages = log_messages; + expected_log_messages.insert(expected_log_messages.end(), after_clear_messages.begin(), + after_clear_messages.end()); + CompareLogMessages(expected_log_messages, read_log_messages); + + // Finally, call FlushTo and ensure that only the 3 logs after the clear remain in the buffer. + std::vector<LogMessage> read_log_messages_after_clear; + std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages_after_clear, nullptr)); + std::unique_ptr<FlushToState> flush_to_state = log_buffer_->CreateFlushToState(1, kLogMaskAll); + EXPECT_TRUE(log_buffer_->FlushTo(test_writer.get(), *flush_to_state, nullptr)); + EXPECT_EQ(7ULL, flush_to_state->start()); + CompareLogMessages(after_clear_messages, read_log_messages_after_clear); +} + +INSTANTIATE_TEST_CASE_P(LogBufferTests, LogBufferTest, + testing::Values("chatty", "serialized", "simple")); |