diff options
Diffstat (limited to 'logd/LogBufferTest.cpp')
| -rw-r--r-- | logd/LogBufferTest.cpp | 458 |
1 files changed, 0 insertions, 458 deletions
diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp deleted file mode 100644 index cb9f4284b..000000000 --- a/logd/LogBufferTest.cpp +++ /dev/null @@ -1,458 +0,0 @@ -/* - * 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; - { - auto lock = std::lock_guard{logd_lock}; - 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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_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::lock_guard{logd_lock}; - reader_list_.reader_threads().back()->Release(); - } - while (!released) { - usleep(5000); - } - { - auto lock = std::lock_guard{logd_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; - { - auto lock = std::lock_guard{logd_lock}; - 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")); |