From a4293131a2bd700094caf8b45c9eb069cf543df7 Mon Sep 17 00:00:00 2001 From: canepat <16927169+canepat@users.noreply.github.com> Date: Wed, 31 Jan 2024 14:47:28 +0100 Subject: [PATCH] rpcdaemon: add support for rotating file logs of external interfaces (#1784) infra: add default settings in logging initialization conan: add spdlog dependency --- conanfile.py | 16 ++-- silkworm/infra/CMakeLists.txt | 2 + silkworm/infra/common/log.hpp | 2 +- silkworm/infra/common/log_test.cpp | 2 + silkworm/rpc/common/interface_log.cpp | 103 +++++++++++++++++++++ silkworm/rpc/common/interface_log.hpp | 43 +++++++++ silkworm/rpc/common/interface_log_test.cpp | 67 ++++++++++++++ 7 files changed, 228 insertions(+), 7 deletions(-) create mode 100644 silkworm/rpc/common/interface_log.cpp create mode 100644 silkworm/rpc/common/interface_log.hpp create mode 100644 silkworm/rpc/common/interface_log_test.cpp diff --git a/conanfile.py b/conanfile.py index bab4e1e4a9..ee76fa0a7d 100644 --- a/conanfile.py +++ b/conanfile.py @@ -14,6 +14,7 @@ from conan import ConanFile + class SilkwormRecipe(ConanFile): settings = 'os', 'compiler', 'build_type', 'arch' generators = 'cmake_find_package' @@ -41,20 +42,22 @@ def requirements(self): self.requires('protobuf/3.21.4') self.requires('roaring/1.1.2') self.requires('snappy/1.1.7') + self.requires('spdlog/1.12.0') self.requires('sqlitecpp/3.3.0') self.requires('tomlplusplus/3.3.0') def configure(self): self.options['asio-grpc'].local_allocator = 'boost_container' - # Currently Conan Center has Windows binaries built only with msvc16 only and mimalloc built only with option override=False. - # In order to build mimalloc with override=True we would need to switch to msvc17 compiler but this would trigger a full rebuild - # from sources of all dependencies wasting a lot of time, so we prefer to keep mimalloc override disabled on Windows. - # The same applies also for boost with option asio_no_deprecated, so we can skip configuration entirely on Windows. + # Conan Center has Windows binaries built only with msvc16 and mimalloc built only with option override=False. + # In order to build mimalloc with override=True we could switch to msvc17 compiler but this would trigger a full + # rebuild from sources of all dependencies increasing build time a lot, so we prefer to keep mimalloc override + # disabled on Windows. + # The same applies also for boost with option asio_no_deprecated, so we skip configuration entirely on Windows. if self.settings.os == 'Windows': return - # Moreover, mimalloc override=True causes a crash on macOS at startup when running rpcdaemon, so we just enable it on Linux + # mimalloc override=True causes a crash on macOS at startup in rpcdaemon, so we just enable it on Linux if self.settings.os == 'Linux': self.options['mimalloc'].override = True @@ -65,7 +68,8 @@ def configure(self): for component in self.boost_components_unused(): setattr(self.options['boost'], 'without_' + component, True) - def boost_components_unused(self): + @staticmethod + def boost_components_unused() -> set[str]: components_all = [ 'atomic', 'chrono', diff --git a/silkworm/infra/CMakeLists.txt b/silkworm/infra/CMakeLists.txt index 0d4a97bd83..468a6b1409 100644 --- a/silkworm/infra/CMakeLists.txt +++ b/silkworm/infra/CMakeLists.txt @@ -21,6 +21,7 @@ find_package(Catch2 REQUIRED) find_package(gRPC REQUIRED) find_package(GTest REQUIRED) find_package(magic_enum REQUIRED) +find_package(spdlog REQUIRED) add_subdirectory(test_util) @@ -50,6 +51,7 @@ set(LIBS_PRIVATE absl::time Boost::container # required for asio-grpc magic_enum::magic_enum + spdlog::spdlog ) # cmake-format: on diff --git a/silkworm/infra/common/log.hpp b/silkworm/infra/common/log.hpp index c3df2cc781..e04aeff84c 100644 --- a/silkworm/infra/common/log.hpp +++ b/silkworm/infra/common/log.hpp @@ -51,7 +51,7 @@ struct Settings { //! \brief Initializes logging facilities //! \note This function is not thread safe as it's meant to be used at start of process and never called again -void init(const Settings& settings); +void init(const Settings& settings = {}); //! \brief Get the current logging verbosity //! \note This function is not thread safe as it's meant to be used in tests diff --git a/silkworm/infra/common/log_test.cpp b/silkworm/infra/common/log_test.cpp index a4c04090ea..c0cd925067 100644 --- a/silkworm/infra/common/log_test.cpp +++ b/silkworm/infra/common/log_test.cpp @@ -79,6 +79,8 @@ TEST_CASE("LogBuffer", "[silkworm][common][log]") { std::stringstream string_cout, string_cerr; test_util::StreamSwap cout_swap{std::cout, string_cout}; test_util::StreamSwap cerr_swap{std::cerr, string_cerr}; + // Make sure logging facility is initialized + init(); SECTION("LogBuffer stores nothing for verbosity higher than default") { check_log_empty(); diff --git a/silkworm/rpc/common/interface_log.cpp b/silkworm/rpc/common/interface_log.cpp new file mode 100644 index 0000000000..3039deca0d --- /dev/null +++ b/silkworm/rpc/common/interface_log.cpp @@ -0,0 +1,103 @@ +/* + Copyright 2024 The Silkworm Authors + + 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 "interface_log.hpp" + +#include +#include + +#include +#include + +namespace silkworm::log { + +class InterfaceLogImpl final { + public: + explicit InterfaceLogImpl(std::string_view name, std::string_view folder, bool auto_flush); + ~InterfaceLogImpl() { + flush(); + } + + [[nodiscard]] std::filesystem::path path() const { + return file_path_; + } + + template + void log(spdlog::format_string_t fmt, Args&&... args) { + rotating_logger_->info(fmt, std::forward(args)...); + } + + void log(std::string_view msg) { + rotating_logger_->info(msg); + if (auto_flush_) { + rotating_logger_->flush(); + } + } + + void flush() { + rotating_logger_->flush(); + } + + private: + std::string name_; + bool auto_flush_; + std::filesystem::path file_path_; + std::size_t max_file_size_{1 * kMebi}; + std::size_t max_files_{10}; + std::shared_ptr rotating_logger_; +}; + +InterfaceLogImpl::InterfaceLogImpl(std::string_view name, std::string_view folder, bool auto_flush) + : name_{name}, + auto_flush_{auto_flush}, + file_path_{folder / std::filesystem::path{name_ + ".log"}}, + rotating_logger_{spdlog::rotating_logger_mt(name_, file_path_.string(), max_file_size_, max_files_)} { + ensure(!name_.empty(), "InterfaceLogImpl: name is empty"); + + // Hard-code log level because we want all-or-nothing in interface log + rotating_logger_->set_level(spdlog::level::info); + + // Customize log pattern to avoid unnecessary fields (log level, logger name) + rotating_logger_->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v"); +} + +InterfaceLog::InterfaceLog(std::string_view name, std::string_view folder, bool auto_flush) + : p_impl_{std::make_unique(name, folder, auto_flush)} { +} + +// An explicit destructor is needed to avoid error: +// invalid application of 'sizeof' to an incomplete type 'silkworm::log::InterfaceLogImpl' +InterfaceLog::~InterfaceLog() { + p_impl_->flush(); +} + +std::filesystem::path InterfaceLog::path() const { + return p_impl_->path(); +} + +void InterfaceLog::log_req(std::string_view msg) { + p_impl_->log("REQ -> {}", msg); +} + +void InterfaceLog::log_rsp(std::string_view msg) { + p_impl_->log("RSP <- {}", msg); +} + +void InterfaceLog::flush() { + p_impl_->flush(); +} + +} // namespace silkworm::log diff --git a/silkworm/rpc/common/interface_log.hpp b/silkworm/rpc/common/interface_log.hpp new file mode 100644 index 0000000000..48610b0135 --- /dev/null +++ b/silkworm/rpc/common/interface_log.hpp @@ -0,0 +1,43 @@ +/* + Copyright 2024 The Silkworm Authors + + 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. +*/ + +#pragma once + +#include +#include +#include + +namespace silkworm::log { + +class InterfaceLogImpl; + +class InterfaceLog final { + public: + explicit InterfaceLog(std::string_view name, std::string_view folder = "logs/", bool auto_flush = false); + ~InterfaceLog(); + + [[nodiscard]] std::filesystem::path path() const; + + void log_req(std::string_view msg); + void log_rsp(std::string_view msg); + + void flush(); + + private: + std::unique_ptr p_impl_; +}; + +} // namespace silkworm::log diff --git a/silkworm/rpc/common/interface_log_test.cpp b/silkworm/rpc/common/interface_log_test.cpp new file mode 100644 index 0000000000..e189c8d2d7 --- /dev/null +++ b/silkworm/rpc/common/interface_log_test.cpp @@ -0,0 +1,67 @@ +/* + Copyright 2024 The Silkworm Authors + + 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 "interface_log.hpp" + +#include +#include +#include + +#include +#include + +#include + +namespace silkworm::log { + +TEST_CASE("InterfaceLog basic", "[infra][common][log]") { + const auto tmp_dir{TemporaryDirectory::get_unique_temporary_path()}; + static int count{0}; + auto ifc_log{std::make_unique("eth_rpc" + std::to_string(++count), tmp_dir.string())}; + REQUIRE(!ifc_log->path().empty()); + ifc_log->log_req(R"({"json":"2.0"})"); + ifc_log->log_rsp(R"({"json":"2.0"})"); + std::ifstream log_ifstream{ifc_log->path().string()}; + + // Log file must be empty before flushing + CHECK(log_ifstream.get() == -1); + CHECK(log_ifstream.eof()); + log_ifstream.clear(); + log_ifstream.seekg(std::ios::beg); + + SECTION("explicit flush") { + // InterfaceLog instance gets flushed here but remains alive until the end + ifc_log->flush(); + } + + SECTION("implicit flush") { + // InterfaceLog instance gets destroyed here and implicitly flushed + ifc_log.reset(); + } + + // First line must be the request + std::string content; + std::getline(log_ifstream, content); + CHECK(absl::StrContains(content, R"(REQ -> {"json":"2.0"})")); + // Second line must be the response + std::getline(log_ifstream, content); + CHECK(absl::StrContains(content, R"(RSP <- {"json":"2.0"})")); + // No other content is present + CHECK(log_ifstream.get() == -1); + CHECK(log_ifstream.eof()); +} + +} // namespace silkworm::log