From b18cf8efc46bfaa2a3a391132fbbb87207ef3b13 Mon Sep 17 00:00:00 2001 From: Tor Egge Date: Fri, 29 Mar 2019 10:54:14 +0100 Subject: Add unit test for logdemon::Watcher. --- logd/CMakeLists.txt | 1 + logd/src/tests/watcher/CMakeLists.txt | 9 + logd/src/tests/watcher/watcher_test.cpp | 287 ++++++++++++++++++++++++++++++++ 3 files changed, 297 insertions(+) create mode 100644 logd/src/tests/watcher/CMakeLists.txt create mode 100644 logd/src/tests/watcher/watcher_test.cpp diff --git a/logd/CMakeLists.txt b/logd/CMakeLists.txt index e16d3bd5179..55afaf9d126 100644 --- a/logd/CMakeLists.txt +++ b/logd/CMakeLists.txt @@ -18,6 +18,7 @@ vespa_define_module( src/tests/proto_converter src/tests/rotate src/tests/rpc_forwarder + src/tests/watcher ) vespa_install_script(src/apps/retention/retention-enforcer.sh vespa-retention-enforcer sbin) diff --git a/logd/src/tests/watcher/CMakeLists.txt b/logd/src/tests/watcher/CMakeLists.txt new file mode 100644 index 00000000000..0bf0a574fa9 --- /dev/null +++ b/logd/src/tests/watcher/CMakeLists.txt @@ -0,0 +1,9 @@ +# Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +vespa_add_executable(logd_watcher_test_app TEST + SOURCES + watcher_test.cpp + DEPENDS + logd + gtest +) +vespa_add_test(NAME logd_watcher_test_app COMMAND logd_watcher_test_app) diff --git a/logd/src/tests/watcher/watcher_test.cpp b/logd/src/tests/watcher/watcher_test.cpp new file mode 100644 index 00000000000..ae0fbd63b90 --- /dev/null +++ b/logd/src/tests/watcher/watcher_test.cpp @@ -0,0 +1,287 @@ +// Copyright 2019 Oath Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using cloud::config::log::LogdConfigBuilder; +using cloud::config::log::LogdConfig; +using config::ConfigSet; +using config::ConfigUri; +using config::IConfigContext; +using config::ConfigContext; +using vespalib::metrics::DummyMetricsManager; +using vespalib::ThreadStackExecutor; +using vespalib::makeLambdaTask; +using namespace std::chrono_literals; + +std::basic_regex rotated_log(R"(vespa.log-[0-9]*-[0-9]*-[0-9]*\.[0-9]*-[0-9]*-[0-9]*)"); + +namespace logdemon { + +namespace { + +struct ConfigFixture { + const std::string configId; + LogdConfigBuilder logdBuilder; + ConfigSet set; + IConfigContext::SP context; + int idcounter; + + ConfigFixture(const std::string & id); + ~ConfigFixture(); + void reload() { context->reload(); } +}; + +ConfigFixture::ConfigFixture(const std::string & id) + : configId(id), + logdBuilder(), + set(), + context(std::make_shared(set)), + idcounter(-1) +{ + logdBuilder.logserver.use = false; + logdBuilder.rotate.size = 1024; + set.addBuilder(configId, &logdBuilder); +} + +ConfigFixture::~ConfigFixture() = default; + +struct DummyForwarder : public Forwarder { + std::mutex lock; + std::condition_variable cond; + std::atomic sendModeCount; + std::vector lines; + DummyForwarder() + : Forwarder(), + lock(), + cond(), + sendModeCount(0), + lines() + { + } + ~DummyForwarder() override = default; + void sendMode() override { ++sendModeCount; } + void forwardLine(std::string_view log_line) override { + std::lock_guard guard(lock); + assert(log_line.size() > 0u); + lines.emplace_back(log_line.substr(0, log_line.size() - 1)); + cond.notify_all(); + } + void flush() override { } + int badLines() const override { return 0; } + void resetBadLines() override { } + std::vector getLines() { + std::lock_guard guard(lock); + return lines; + } + void waitLineCount(size_t lineCount) { + std::unique_lock guard(lock); + cond.wait_for(guard, 10s, [this, lineCount]() { return lineCount <= lines.size(); }); + } +}; + +struct WatcherFixture +{ + Metrics metrics; + LegacyForwarder legacy_fwd; + DummyForwarder fwd; + ConfigSubscriber subscriber; + Watcher watcher; + + WatcherFixture(ConfigFixture &cfg); + ~WatcherFixture(); +}; + +WatcherFixture::WatcherFixture(ConfigFixture &cfg) + : metrics(DummyMetricsManager::create()), + legacy_fwd(metrics), + fwd(), + subscriber(legacy_fwd, config::ConfigUri(cfg.configId, cfg.context)), + watcher(subscriber, fwd) +{ + subscriber.latch(); +} + +WatcherFixture::~WatcherFixture() = default; + +} + +class WatcherTest : public ::testing::Test { +protected: + std::unique_ptr _cfg; + std::unique_ptr _watcher; + ThreadStackExecutor _executor; + + void setup_watcher(); + void run_watcher(); + void stop_watcher(); + void log_line(const std::string &line); + void assert_lines(const std::vector &lines); + void remove_files(); + void remove_rotated(); + int count_rotated(); +public: + WatcherTest(); + ~WatcherTest(); +}; + +WatcherTest::WatcherTest() + : _executor(1, 256 * 1024) +{ + remove_files(); + setenv("VESPA_LOG_TARGET", "file:vespa.log", true); + vespalib::mkdir("var/db/vespa", true); // for logd.donestate + _cfg = std::make_unique("testconfigid"); +} + +WatcherTest::~WatcherTest() +{ + remove_files(); +} + +void +WatcherTest::setup_watcher() +{ + _watcher = std::make_unique(*_cfg); +} + +void +WatcherTest::run_watcher() +{ + // Spin off watcher task + _executor.execute(makeLambdaTask([this]() { _watcher->watcher.watchfile(); })); +} + +void +WatcherTest::stop_watcher() +{ + _cfg->reload(); + _executor.sync(); +} + +void +WatcherTest::log_line(const std::string &line) +{ + std::ofstream log_file("vespa.log", std::ios::out | std::ios::app); + log_file << line << std::endl; +} + +void +WatcherTest::assert_lines(const std::vector &lines) +{ + EXPECT_EQ(lines, _watcher->fwd.getLines()); +} + +void +WatcherTest::remove_files() +{ + vespalib::rmdir("var", true); + remove_rotated(); + vespalib::unlink("vespa.log"); +} + +void +WatcherTest::remove_rotated() +{ + auto dirlist = vespalib::listDirectory("."); + for (const auto &entry : dirlist) { + if (std::regex_match(entry.data(), entry.data() + entry.size(), rotated_log)) { + vespalib::unlink(entry); + } + } +} + +int +WatcherTest::count_rotated() +{ + int result = 0; + auto dirlist = vespalib::listDirectory("."); + for (const auto &entry : dirlist) { + if (std::regex_match(entry.data(), entry.data() + entry.size(), rotated_log)) { + ++result; + } + } + return result; +} + +TEST_F(WatcherTest, require_that_watching_no_logging_works) +{ + setup_watcher(); + run_watcher(); + stop_watcher(); + assert_lines({}); + EXPECT_EQ(0, count_rotated()); +} + +TEST_F(WatcherTest, require_that_watching_simple_logging_works) +{ + setup_watcher(); + run_watcher(); + log_line("foo"); + _watcher->fwd.waitLineCount(1); + stop_watcher(); + EXPECT_EQ(0, count_rotated()); + assert_lines({"foo"}); +} + +TEST_F(WatcherTest, require_that_watching_can_resume) +{ + setup_watcher(); + run_watcher(); + log_line("foo"); + _watcher->fwd.waitLineCount(1); + stop_watcher(); + assert_lines({"foo"}); + setup_watcher(); + run_watcher(); + log_line("bar"); + log_line("baz"); + _watcher->fwd.waitLineCount(2); + stop_watcher(); + assert_lines({"bar", "baz"}); + // remove state file. Old entry will resurface + vespalib::unlink("var/db/vespa/logd.donestate"); + setup_watcher(); + run_watcher(); + _watcher->fwd.waitLineCount(3); + stop_watcher(); + assert_lines({"foo", "bar", "baz"}); +} + +TEST_F(WatcherTest, require_that_watching_can_rotate_log_files) +{ + setup_watcher(); + run_watcher(); + std::vector exp_lines; + for (int i = 0; i < 100; ++i) { + std::ostringstream os; + os << "this is a malformatted " << std::setw(3) << i << + std::setw(0) << " line but who cares ?"; + log_line(os.str()); + exp_lines.push_back(os.str()); + std::this_thread::sleep_for(100ms); + if (count_rotated() > 0) { + break; + } + } + _watcher->fwd.waitLineCount(exp_lines.size()); + stop_watcher(); + assert_lines(exp_lines); + EXPECT_LT(0, count_rotated()); +} + +} + +GTEST_MAIN_RUN_ALL_TESTS() -- cgit v1.2.3