From 43f3f761f0cdefe835ce5eb5989a5dde81f5096e Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Thu, 14 May 2020 22:28:09 -0700 Subject: [PATCH] logd: add LogBufferTest.cpp Add a standalone test of log buffers that does not interact with the logd running on the device. Test: this new test Change-Id: Ie4ecc50289ef164aa47cc72ddeeb9b28e776db94 --- logd/Android.bp | 57 ++++++ logd/{tests => }/AndroidTest.xml | 0 logd/LogBufferTest.cpp | 327 +++++++++++++++++++++++++++++++ logd/{tests => }/logd_test.cpp | 2 +- logd/tests/Android.bp | 68 ------- 5 files changed, 385 insertions(+), 69 deletions(-) rename logd/{tests => }/AndroidTest.xml (100%) create mode 100644 logd/LogBufferTest.cpp rename logd/{tests => }/logd_test.cpp (99%) delete mode 100644 logd/tests/Android.bp diff --git a/logd/Android.bp b/logd/Android.bp index d79e25892..32bfefea2 100644 --- a/logd/Android.bp +++ b/logd/Android.bp @@ -110,3 +110,60 @@ prebuilt_etc { src: "logtagd.rc", sub_dir: "init", } + +// ----------------------------------------------------------------------------- +// Unit tests. +// ----------------------------------------------------------------------------- + +cc_defaults { + name: "logd-unit-test-defaults", + + cflags: [ + "-fstack-protector-all", + "-g", + "-Wall", + "-Wextra", + "-Werror", + "-fno-builtin", + + "-DAUDITD_LOG_TAG=1003", + "-DCHATTY_LOG_TAG=1004", + ], + + srcs: [ + "logd_test.cpp", + "LogBufferTest.cpp", + ], + + static_libs: [ + "libbase", + "libcutils", + "liblog", + "liblogd", + "libselinux", + ], +} + +// Build tests for the logger. Run with: +// adb shell /data/nativetest/logd-unit-tests/logd-unit-tests +cc_test { + name: "logd-unit-tests", + defaults: ["logd-unit-test-defaults"], +} + +cc_test { + name: "CtsLogdTestCases", + defaults: ["logd-unit-test-defaults"], + multilib: { + lib32: { + suffix: "32", + }, + lib64: { + suffix: "64", + }, + }, + test_suites: [ + "cts", + "vts10", + ], +} diff --git a/logd/tests/AndroidTest.xml b/logd/AndroidTest.xml similarity index 100% rename from logd/tests/AndroidTest.xml rename to logd/AndroidTest.xml diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp new file mode 100644 index 000000000..806fd1626 --- /dev/null +++ b/logd/LogBufferTest.cpp @@ -0,0 +1,327 @@ +/* + * Copyright (C) 2014 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 "LogBuffer.h" + +#include + +#include +#include + +#include +#include +#include + +#include "ChattyLogBuffer.h" +#include "LogReaderList.h" +#include "LogReaderThread.h" +#include "LogStatistics.h" +#include "LogTags.h" +#include "LogWhiteBlackList.h" +#include "LogWriter.h" + +using android::base::Join; +using android::base::StringPrintf; + +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; +} + +class TestWriter : public LogWriter { + public: + TestWriter(std::vector>* msgs, bool* released) + : LogWriter(0, true, true), msgs_(msgs), released_(released) {} + bool Write(const logger_entry& entry, const char* message) override { + msgs_->emplace_back(entry, std::string(message, entry.len)); + return true; + } + + void Release() { + if (released_) *released_ = true; + } + + std::string name() const override { return "test_writer"; } + + private: + std::vector>* msgs_; + bool* released_; +}; + +class LogBufferTest : public testing::Test { + protected: + void SetUp() override { + log_buffer_.reset(new ChattyLogBuffer(&reader_list_, &tags_, &prune_, &stats_)); + } + + void FixupMessages(std::vector>* messages) { + for (auto& [entry, message] : *messages) { + entry.hdr_size = sizeof(logger_entry); + entry.len = message.size(); + } + } + + void LogMessages(const std::vector>& messages) { + for (auto& [entry, message] : messages) { + log_buffer_->Log(static_cast(entry.lid), log_time(entry.sec, entry.nsec), + entry.uid, entry.pid, entry.tid, message.c_str(), message.size()); + } + } + + std::vector CompareLoggerEntries(const logger_entry& expected, + const logger_entry& result) { + std::vector errors; + if (expected.len != result.len) { + errors.emplace_back( + StringPrintf("len: %" 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: %" PRIi32 " vs %" PRIi32, expected.pid, result.pid)); + } + if (expected.tid != result.tid) { + errors.emplace_back( + StringPrintf("tid: %" PRIu32 " vs %" PRIu32, expected.tid, result.tid)); + } + if (expected.sec != result.sec) { + errors.emplace_back( + StringPrintf("sec: %" PRIu32 " vs %" PRIu32, expected.sec, result.sec)); + } + if (expected.nsec != result.nsec) { + errors.emplace_back( + StringPrintf("nsec: %" PRIu32 " vs %" PRIu32, expected.nsec, result.nsec)); + } + if (expected.lid != result.lid) { + errors.emplace_back( + StringPrintf("lid: %" PRIu32 " vs %" PRIu32, expected.lid, result.lid)); + } + if (expected.uid != result.uid) { + errors.emplace_back( + StringPrintf("uid: %" PRIu32 " vs %" PRIu32, expected.uid, result.uid)); + } + return errors; + } + + std::string CompareMessages(const std::string& expected, const std::string& result) { + if (expected == result) { + return {}; + } + auto shorten_string = [](const std::string& in) { + if (in.size() > 10) { + return in.substr(0, 10) + "..."; + } + return in; + }; + + 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 = shorten_string(expected); + auto result_short = shorten_string(result); + return StringPrintf("msg: %s vs %s", expected_short.c_str(), result_short.c_str()); + } + + auto expected_short = shorten_string(expected.substr(diff_index)); + auto result_short = shorten_string(result.substr(diff_index)); + return StringPrintf("msg: index %zu: %s vs %s", diff_index, expected_short.c_str(), + result_short.c_str()); + } + + 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].first, result[i].first); + auto msg_error = CompareMessages(expected[i].second, result[i].second); + if (!msg_error.empty()) { + errors.emplace_back(msg_error); + } + if (!errors.empty()) { + GTEST_LOG_(ERROR) << "Mismatch log message " << i << " " << Join(errors, " "); + ++num_errors; + } + } + EXPECT_EQ(0U, num_errors); + } + + LogReaderList reader_list_; + LogTags tags_; + PruneList prune_; + LogStatistics stats_{false}; + std::unique_ptr log_buffer_; +}; + +TEST_F(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_F(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. +std::pair 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_F(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); +} diff --git a/logd/tests/logd_test.cpp b/logd/logd_test.cpp similarity index 99% rename from logd/tests/logd_test.cpp rename to logd/logd_test.cpp index 570ff2a24..ed34ea413 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/logd_test.cpp @@ -39,7 +39,7 @@ #include #endif -#include "../LogReader.h" // pickup LOGD_SNDTIMEO +#include "LogReader.h" // pickup LOGD_SNDTIMEO #ifdef __ANDROID__ static void send_to_control(char* buf, size_t len) { diff --git a/logd/tests/Android.bp b/logd/tests/Android.bp deleted file mode 100644 index 9a5defa17..000000000 --- a/logd/tests/Android.bp +++ /dev/null @@ -1,68 +0,0 @@ -// -// Copyright (C) 2014 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. -// - -// ----------------------------------------------------------------------------- -// Unit tests. -// ----------------------------------------------------------------------------- - -cc_defaults { - name: "logd-unit-test-defaults", - - cflags: [ - "-fstack-protector-all", - "-g", - "-Wall", - "-Wextra", - "-Werror", - "-fno-builtin", - - "-DAUDITD_LOG_TAG=1003", - "-DCHATTY_LOG_TAG=1004", - ], - - srcs: ["logd_test.cpp"], - - static_libs: [ - "libbase", - "libcutils", - "libselinux", - "liblog", - ], -} - -// Build tests for the logger. Run with: -// adb shell /data/nativetest/logd-unit-tests/logd-unit-tests -cc_test { - name: "logd-unit-tests", - defaults: ["logd-unit-test-defaults"], -} - -cc_test { - name: "CtsLogdTestCases", - defaults: ["logd-unit-test-defaults"], - multilib: { - lib32: { - suffix: "32", - }, - lib64: { - suffix: "64", - }, - }, - test_suites: [ - "cts", - "vts10", - ], -}