diff --git a/core/include/userver/logging/log.hpp b/core/include/userver/logging/log.hpp index 43e9d9640064..dc2c6f039372 100644 --- a/core/include/userver/logging/log.hpp +++ b/core/include/userver/logging/log.hpp @@ -28,7 +28,7 @@ LoggerPtr SetDefaultLogger(LoggerPtr); /// Sets new log level for default logger void SetDefaultLoggerLevel(Level); -void SetLoggerLevel(LoggerPtr, Level); +void SetLoggerLevel(const LoggerPtr&, Level); /// Returns log level for default logger Level GetDefaultLoggerLevel(); @@ -41,7 +41,7 @@ Level GetLoggerLevel(const LoggerPtr& logger); void LogFlush(); /// Forces flush of `logger` message queue -void LogFlush(LoggerPtr logger); +void LogFlush(const LoggerPtr& logger); namespace impl { diff --git a/core/src/logging/dynamic_debug_test.cpp b/core/src/logging/dynamic_debug_test.cpp index 849f8af4c974..3c0dd96824ce 100644 --- a/core/src/logging/dynamic_debug_test.cpp +++ b/core/src/logging/dynamic_debug_test.cpp @@ -1,5 +1,7 @@ #include +#include + #include #include #include @@ -12,11 +14,12 @@ TEST_F(LoggingTest, DynamicDebugBasic) { LOG_INFO() << "before"; const std::string location = USERVER_FILEPATH; - logging::AddDynamicDebugLog(location, 17); + logging::AddDynamicDebugLog(location, 10001); +#line 10001 LOG_INFO() << "123"; - logging::RemoveDynamicDebugLog(location, 17); + logging::RemoveDynamicDebugLog(location, 10001); LOG_INFO() << "after"; @@ -42,10 +45,10 @@ TEST_F(LoggingTest, DynamicDebugAnyLine) { LOG_INFO() << "after"; - EXPECT_FALSE(LoggedTextContains("before")); - EXPECT_TRUE(LoggedTextContains("123")); - EXPECT_TRUE(LoggedTextContains("456")); - EXPECT_FALSE(LoggedTextContains("after")); + EXPECT_THAT(GetStreamString(), testing::Not(testing::HasSubstr("before"))); + EXPECT_THAT(GetStreamString(), testing::HasSubstr("123")); + EXPECT_THAT(GetStreamString(), testing::HasSubstr("456")); + EXPECT_THAT(GetStreamString(), testing::Not(testing::HasSubstr("after"))); logging::SetDefaultLoggerLevel(logging::Level::kInfo); } @@ -56,10 +59,11 @@ TEST_F(LoggingTest, DynamicDebugAnyLineRemove) { LOG_INFO() << "before"; const std::string location = USERVER_FILEPATH; - logging::AddDynamicDebugLog(location, 63); - logging::AddDynamicDebugLog(location, 64); + logging::AddDynamicDebugLog(location, 20001); + logging::AddDynamicDebugLog(location, 20002); logging::RemoveDynamicDebugLog(location, logging::kAnyLine); +#line 20001 LOG_INFO() << "123"; LOG_INFO() << "456"; diff --git a/core/src/logging/log.cpp b/core/src/logging/log.cpp index 2c1517a89a37..4916efa5ec51 100644 --- a/core/src/logging/log.cpp +++ b/core/src/logging/log.cpp @@ -65,7 +65,12 @@ void SetDefaultLoggerLevel(Level level) { UpdateLogLevelCache(); } -void SetLoggerLevel(LoggerPtr logger, Level level) { logger->SetLevel(level); } +void SetLoggerLevel(const LoggerPtr& logger, Level level) { + logger->SetLevel(level); + if (logger == DefaultLoggerOptional()) { + UpdateLogLevelCache(); + } +} Level GetDefaultLoggerLevel() { return static_cast(DefaultLogger()->GetLevel()); @@ -79,7 +84,7 @@ Level GetLoggerLevel(const LoggerPtr& logger) { return logger->GetLevel(); } void LogFlush() { DefaultLogger()->Flush(); } -void LogFlush(LoggerPtr logger) { logger->Flush(); } +void LogFlush(const LoggerPtr& logger) { logger->Flush(); } namespace impl { diff --git a/core/src/logging/log_message_test.cpp b/core/src/logging/log_message_test.cpp index 83ec319c4fdf..3ee83702ed70 100644 --- a/core/src/logging/log_message_test.cpp +++ b/core/src/logging/log_message_test.cpp @@ -7,6 +7,7 @@ #include #include +#include #include #include @@ -74,7 +75,8 @@ TEST_F(LoggingTest, TskvEncodeKeyWithDot) { logging::LogExtra le; le.Extend("http.port.ipv4", "4040"); LOG_CRITICAL() << "line 1\nline 2" << le; - EXPECT_EQ(LoggedText(), "line 1\\nline 2\thttp_port_ipv4=4040"); + EXPECT_THAT(GetStreamString(), + testing::HasSubstr("line 1\\nline 2\thttp_port_ipv4=4040")); } TEST_F(LoggingTest, FloatingPoint) { @@ -139,9 +141,9 @@ TEST_F(LoggingTest, TracefulExceptionDebug) { LOG_CRITICAL() << utils::TracefulException("traceful exception"); - EXPECT_TRUE(LoggedTextContains("traceful exception")) + EXPECT_THAT(GetStreamString(), testing::HasSubstr("traceful exception")) << "traceful exception is missing its message"; - EXPECT_TRUE(LoggedTextContains("\tstacktrace=")) + EXPECT_THAT(GetStreamString(), testing::HasSubstr("\tstacktrace=")) << "traceful exception is missing its trace"; } @@ -169,7 +171,7 @@ TEST_F(LoggingTest, AttachedException) { << "missing plain exception message"; EXPECT_TRUE(LoggedTextContains("plain exception with additional info")) << "traceful exception message malformed"; - EXPECT_TRUE(LoggedTextContains("\tstacktrace=")) + EXPECT_THAT(GetStreamString(), testing::HasSubstr("\tstacktrace=")) << "traceful exception missing its trace"; } diff --git a/core/src/logging/log_test.cpp b/core/src/logging/log_test.cpp index 5f702b36b04d..b6b2f0540518 100644 --- a/core/src/logging/log_test.cpp +++ b/core/src/logging/log_test.cpp @@ -1,10 +1,7 @@ #include -#include -#include -#include +#include #include -#include #include #include @@ -73,30 +70,16 @@ TEST_F(LoggingTest, DocsData) { LOG_ERROR() << "This is unbelievable, fix me, please!"; /// [Sample logging usage] - bool flag = true; + const bool flag = true; /// [Example set custom logging usage] - logging::Level level = flag ? logging::Level::kDebug : logging::Level::kInfo; + const auto level = flag ? logging::Level::kDebug : logging::Level::kInfo; LOG(level) << "some text"; /// [Example set custom logging usage] } UTEST_F(SocketLoggingTest, Test) { - engine::Mutex mt; - engine::ConditionVariable cv; - auto task = utils::Async("server task", &SocketLoggingTest::Server, this, - std::ref(cv)); - - std::unique_lock lock(mt); - if (!cv.Wait(lock, [&]() { return IsStarts(); })) { - FAIL(); - } - LOG_ERROR() << "test"; - if (!cv.Wait(lock, [&]() { return IsRead(); })) { - FAIL(); - } - - EXPECT_EQ("test", LoggedText()); + EXPECT_EQ("test", NextLoggedText()); } USERVER_NAMESPACE_END diff --git a/core/src/logging/logging_test.hpp b/core/src/logging/logging_test.hpp index 444efcca3c84..c5f44b0a0727 100644 --- a/core/src/logging/logging_test.hpp +++ b/core/src/logging/logging_test.hpp @@ -1,26 +1,15 @@ #pragma once #include - -#include +#include #include #include #include #include -#include - -#include -#include -#include #include #include -#include -#include - -#include -#include USERVER_NAMESPACE_BEGIN @@ -29,6 +18,7 @@ inline std::shared_ptr MakeLoggerFromSink( std::shared_ptr sink_ptr, logging::Format format) { auto logger = std::make_shared(format, logger_name); logger->AddSink(std::move(sink_ptr)); + logger->SetPattern(logging::GetSpdlogPattern(format)); return logger; } @@ -39,155 +29,76 @@ inline std::shared_ptr MakeNamedStreamLogger( return MakeLoggerFromSink(logger_name, sink, format); } -inline std::shared_ptr MakeSocketLogger( - const std::string& logger_name, std::string& filename, - logging::Format format) { - auto sink = std::make_shared(filename); - return MakeLoggerFromSink(logger_name, sink, format); +inline std::string_view GetTextKey(logging::Format format) { + return format == logging::Format::kLtsv ? "text:" : "text="; } -class SocketLoggingTest : public ::testing::Test { - public: - static constexpr char socket_file[] = "socket"; - static constexpr size_t buffer_size = 1024; +inline std::string ParseLoggedText(std::string_view log_record, + logging::Format format) { + const auto text_key = GetTextKey(format); - std::string LoggedText() const { - logging::LogFlush(); - std::string str(buffer_); - std::string text_key = "text="; - - const auto text_begin = str.find(text_key); - const std::string from_text = - text_begin == std::string::npos - ? str - : str.substr(text_begin + text_key.length()); - - const auto text_end = from_text.find('\t'); - return text_end == std::string::npos ? from_text - : from_text.substr(0, text_end); + const auto text_begin = log_record.find(text_key); + if (text_begin != std::string_view::npos) { + log_record.remove_prefix(text_begin + text_key.length()); } - void Server(engine::ConditionVariable& cv) { - engine::io::Socket connection = socket_.Accept({}); - - starts_.store(true); - cv.NotifyOne(); - while (!engine::current_task::ShouldCancel()) { - auto res = connection.RecvSome(buffer_ + bytes_read_, - buffer_size - bytes_read_, {}); - - bytes_read_ += static_cast(res); - UASSERT(bytes_read_ < buffer_size); - cv.NotifyOne(); - } + const auto text_end = log_record.find_first_of("\t\r\n"); + if (text_end != std::string_view::npos) { + log_record = log_record.substr(0, text_end); } - bool IsStarts() const { return starts_.load(); } - bool IsRead() const { return bytes_read_.load() != 0; } + return std::string{log_record}; +} +class DefaultLoggerFixture : public ::testing::Test { protected: - SocketLoggingTest() - : socket_(engine::io::AddrDomain::kUnix, - engine::io::SocketType::kStream) { - unlink(socket_file); - - struct sockaddr_un addr {}; - addr.sun_family = AF_UNIX; - std::strncpy(addr.sun_path, socket_file, std::strlen(socket_file)); - - socket_.Bind(engine::io::Sockaddr(static_cast(&addr))); - - socket_.Listen(); - } - - void SetUp() override { - static std::string logger_name = "socket_logger"; - std::string filename(socket_file); - auto logger = - MakeSocketLogger(logger_name, filename, logging::Format::kTskv); - logger->SetPattern(logging::GetSpdlogPattern(logging::Format::kTskv)); - logger->SetLevel(logging::Level::kError); - old_ = logging::SetDefaultLogger(logger); - - logging::LogFlush(); - ClearLog(); - } - - void TearDown() override { - if (old_) { - // Discard logs from SetDefaultLogger + ~DefaultLoggerFixture() override { + if (old_logger_) { + // Discard logs from within SetDefaultLogger logging::SetDefaultLoggerLevel(logging::Level::kNone); logging::LogFlush(); - logging::SetDefaultLogger(old_); - old_.reset(); + logging::SetDefaultLogger(old_logger_); + old_logger_.reset(); } } - private: - void ClearLog() { bytes_read_ = 0; } + void SetDefaultLogger(logging::LoggerPtr new_logger) { + // Ignore clang-tidy request to make the method 'static' + [[maybe_unused]] auto* const self = this; - engine::io::Socket socket_; - std::atomic starts_; + const auto old_level = logging::GetLoggerLevel(new_logger); + // Discard logs from within SetLoggerLevel itself + logging::SetLoggerLevel(new_logger, logging::Level::kNone); - char buffer_[buffer_size]{}; - std::atomic bytes_read_{0}; + logging::SetDefaultLogger(new_logger); + logging::SetLoggerLevel(new_logger, old_level); + } - logging::LoggerPtr old_; + private: + logging::LoggerPtr old_logger_{logging::DefaultLogger()}; }; -class LoggingTestBase : public ::testing::Test { +class LoggingTestBase : public DefaultLoggerFixture { protected: - LoggingTestBase(logging::Format format, std::string_view text_key) - : format_(format), text_key_(text_key) {} - - void SetUp() override { - old_ = logging::SetDefaultLogger(MakeStreamLogger(sstream)); - - // Discard logs from SetDefaultLogger - logging::LogFlush(); - ClearLog(); - } - - void TearDown() override { - if (old_) { - // Discard logs from SetDefaultLogger - logging::SetDefaultLoggerLevel(logging::Level::kNone); - logging::LogFlush(); - - logging::SetDefaultLogger(old_); - old_.reset(); - } + LoggingTestBase(logging::Format format) : format_(format) { + SetDefaultLogger(MakeStreamLogger(sstream_)); } logging::LoggerPtr MakeStreamLogger(std::ostream& stream) const { - std::ostringstream os; - os << this; - auto logger = MakeNamedStreamLogger(os.str(), stream, format_); - logger->SetPattern(logging::GetSpdlogPattern(format_)); - return logger; + return MakeNamedStreamLogger("test-stream-logger", stream, format_); } std::string LoggedText() const { logging::LogFlush(); - const std::string str = sstream.str(); - - const auto text_begin = str.find(text_key_); - const std::string from_text = - text_begin == std::string::npos - ? str - : str.substr(text_begin + text_key_.length()); - - const auto text_end = from_text.rfind('\n'); - return text_end == std::string::npos ? from_text - : from_text.substr(0, text_end); + return ParseLoggedText(sstream_.str(), format_); } bool LoggedTextContains(const std::string& str) const { return LoggedText().find(str) != std::string::npos; } - void ClearLog() { sstream.str({}); } + void ClearLog() { sstream_.str({}); } template std::string ToStringViaLogging(const T& value) { @@ -197,24 +108,21 @@ class LoggingTestBase : public ::testing::Test { return result; } - std::string GetStreamString() const { return sstream.str(); } + std::string GetStreamString() const { return sstream_.str(); } private: const logging::Format format_; - const std::string_view text_key_; - logging::LoggerPtr old_; - - std::ostringstream sstream; + std::ostringstream sstream_; }; class LoggingTest : public LoggingTestBase { protected: - LoggingTest() : LoggingTestBase(logging::Format::kTskv, "text=") {} + LoggingTest() : LoggingTestBase(logging::Format::kTskv) {} }; class LoggingLtsvTest : public LoggingTestBase { protected: - LoggingLtsvTest() : LoggingTestBase(logging::Format::kLtsv, "text:") {} + LoggingLtsvTest() : LoggingTestBase(logging::Format::kLtsv) {} }; USERVER_NAMESPACE_END diff --git a/core/src/logging/socket_logging_test.hpp b/core/src/logging/socket_logging_test.hpp new file mode 100644 index 000000000000..fd669426aa40 --- /dev/null +++ b/core/src/logging/socket_logging_test.hpp @@ -0,0 +1,106 @@ +#pragma once + +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +USERVER_NAMESPACE_BEGIN + +inline std::shared_ptr MakeSocketLogger( + const std::string& logger_name, std::string filename, + logging::Format format) { + auto sink = std::make_shared(std::move(filename)); + return MakeLoggerFromSink(logger_name, sink, format); +} + +class SocketLoggingTest : public DefaultLoggerFixture { + public: + std::string NextLoggedText() { + logging::LogFlush(); + return ParseLoggedText(NextReceivedMessage(), logging::Format::kTskv); + } + + std::string NextReceivedMessage() { + std::string result; + if (!messages_consumer_.Pop( + result, engine::Deadline::FromDuration(utest::kMaxTestWaitTime))) { + throw std::runtime_error("Timed out while waiting for the next message"); + } + return result; + } + + protected: + SocketLoggingTest() + : socket_file_(fs::blocking::TempFile::Create()), + socket_(engine::io::AddrDomain::kUnix, engine::io::SocketType::kStream), + messages_(MessagesQueue::Create()), + messages_consumer_(messages_->GetConsumer()) { + SetUpSocketFile(); + SetUpLogger(); + StartServer(); + } + + ~SocketLoggingTest() override { server_task_.SyncCancel(); } + + private: + using MessagesQueue = concurrent::SpscQueue; + + void RunServer() { + engine::io::Socket connection = socket_.Accept({}); + const auto producer = messages_->GetProducer(); + std::string buffer(kBufferSize, '\0'); + + while (!engine::current_task::ShouldCancel()) { + const auto bytes_received = + connection.RecvSome(buffer.data(), buffer.size(), {}); + if (bytes_received == 0) break; + + const bool success = producer.Push(buffer.substr(0, bytes_received)); + UINVARIANT(success, "Failed to push a message"); + } + } + + void SetUpSocketFile() { + fs::blocking::RemoveSingleFile(socket_file_.GetPath()); + + struct sockaddr_un addr {}; + addr.sun_family = AF_UNIX; + std::strncpy(addr.sun_path, socket_file_.GetPath().data(), + socket_file_.GetPath().size()); + + socket_.Bind(engine::io::Sockaddr(static_cast(&addr))); + + socket_.Listen(); + } + + void StartServer() { + server_task_ = + utils::CriticalAsync("log-server", &SocketLoggingTest::RunServer, this); + } + + void SetUpLogger() { + const auto logger = MakeSocketLogger( + "socket_logger", socket_file_.GetPath(), logging::Format::kTskv); + // Discard logs from the network interaction. + logger->SetLevel(logging::Level::kError); + SetDefaultLogger(logger); + } + + static constexpr std::size_t kBufferSize = 4096; + + fs::blocking::TempFile socket_file_; + engine::io::Socket socket_; + std::shared_ptr messages_; + MessagesQueue::Consumer messages_consumer_; + engine::TaskWithResult server_task_; +}; + +USERVER_NAMESPACE_END diff --git a/core/src/logging/unix_socket_sink.hpp b/core/src/logging/unix_socket_sink.hpp index 541caef966f4..c86475c69019 100644 --- a/core/src/logging/unix_socket_sink.hpp +++ b/core/src/logging/unix_socket_sink.hpp @@ -3,36 +3,33 @@ #include #include -// this header must be included before any spdlog headers -// to override spdlog's level names -#include - #include #include USERVER_NAMESPACE_BEGIN + namespace logging { namespace impl { + class UnixSocketClient final { public: UnixSocketClient() = default; UnixSocketClient(const UnixSocketClient&) = delete; UnixSocketClient(UnixSocketClient&&) = default; - UnixSocketClient& operator=(const UnixSocketClient&) = delete; UnixSocketClient& operator=(UnixSocketClient&&) = default; + ~UnixSocketClient(); void connect(const spdlog::filename_t& filename); void send(const char* data, size_t n_bytes); void close(); - ~UnixSocketClient(); - private: int socket_{-1}; }; + } // namespace impl template @@ -41,7 +38,7 @@ class SocketSink final : public spdlog::sinks::base_sink { using filename_t = spdlog::filename_t; using sink = spdlog::sinks::base_sink; - SocketSink(filename_t filename) : filename_{std::move(filename)} { + explicit SocketSink(filename_t filename) : filename_{std::move(filename)} { client_.connect(filename_); }