From 9bc784050e90920138bab99d4f4517db822c519f Mon Sep 17 00:00:00 2001 From: Larry Osterman Date: Wed, 7 Jun 2023 13:41:24 -0700 Subject: [PATCH] Moved logger back to cerr (#4702) * Moved logger back to cerr * Simplified stream logger experience; removed need for std::endl --- .../src/amqp/claim_based_security.cpp | 4 +- .../azure-core-amqp/src/amqp/management.cpp | 2 +- .../src/amqp/message_receiver.cpp | 4 +- .../src/amqp/message_sender.cpp | 2 +- sdk/core/azure-core-amqp/src/amqp/session.cpp | 2 +- .../src/network/socket_transport.cpp | 2 +- sdk/core/azure-core/CHANGELOG.md | 2 +- sdk/core/azure-core/README.md | 3 +- .../azure/core/internal/diagnostics/log.hpp | 17 +++++- .../src/environment_log_level_listener.cpp | 19 +++---- sdk/core/azure-core/src/logger.cpp | 10 ++-- .../environment_log_level_listener_test.cpp | 32 +++++------ sdk/core/azure-core/test/ut/logging_test.cpp | 54 +++++++++---------- 13 files changed, 81 insertions(+), 72 deletions(-) diff --git a/sdk/core/azure-core-amqp/src/amqp/claim_based_security.cpp b/sdk/core/azure-core-amqp/src/amqp/claim_based_security.cpp index 9cf495378..b4eababe0 100644 --- a/sdk/core/azure-core-amqp/src/amqp/claim_based_security.cpp +++ b/sdk/core/azure-core-amqp/src/amqp/claim_based_security.cpp @@ -121,7 +121,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { if (cbs->m_traceEnabled) { Log::Stream(Logger::Level::Informational) - << "OnCbsOpenComplete: " << OpenResultStringFromLowLevel(openCompleteResult) << std::endl; + << "OnCbsOpenComplete: " << OpenResultStringFromLowLevel(openCompleteResult); } cbs->m_openResultQueue.CompleteOperation(CbsOpenResultStateFromLowLevel(openCompleteResult)); } @@ -161,7 +161,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { << "OnCbsOperationComplete: " << OperationResultStringFromLowLevel(operationCompleteResult) << " StatusCode: " << statusCode << " StatusDescription: " - << (statusDescription ? std::string(statusDescription) : "(NULL)") << std::endl; + << (statusDescription ? std::string(statusDescription) : "(NULL)"); } cbs->m_operationResultQueue.CompleteOperation( diff --git a/sdk/core/azure-core-amqp/src/amqp/management.cpp b/sdk/core/azure-core-amqp/src/amqp/management.cpp index 55f15238f..ac4b91e2c 100644 --- a/sdk/core/azure-core-amqp/src/amqp/management.cpp +++ b/sdk/core/azure-core-amqp/src/amqp/management.cpp @@ -184,7 +184,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { if (management->m_options.EnableTrace) { Log::Stream(Logger::Level::Informational) - << "OnManagementOpenComplete: " << std::to_string(openResult) << std::endl; + << "OnManagementOpenComplete: " << std::to_string(openResult); } management->m_openCompleteQueue.CompleteOperation(openResult); } diff --git a/sdk/core/azure-core-amqp/src/amqp/message_receiver.cpp b/sdk/core/azure-core-amqp/src/amqp/message_receiver.cpp index cadb4c370..5b9356738 100644 --- a/sdk/core/azure-core-amqp/src/amqp/message_receiver.cpp +++ b/sdk/core/azure-core-amqp/src/amqp/message_receiver.cpp @@ -109,7 +109,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { // Log that an error occurred. Log::Stream(Logger::Level::Error) << "Message receiver link detached: " + error.Condition.ToString() << ": " - << error.Description << std::endl; + << error.Description; // Cache the error we received in the OnDetach notification so we can return it to the user on // the next send which fails. @@ -237,7 +237,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { { Log::Stream(Logger::Level::Verbose) << "Message receiver changed state. New: " << MESSAGE_RECEIVER_STATEStrings[newState] - << " Old: " << MESSAGE_RECEIVER_STATEStrings[oldState] << std::endl; + << " Old: " << MESSAGE_RECEIVER_STATEStrings[oldState]; ; } diff --git a/sdk/core/azure-core-amqp/src/amqp/message_sender.cpp b/sdk/core/azure-core-amqp/src/amqp/message_sender.cpp index 58cad4c6e..7873770f1 100644 --- a/sdk/core/azure-core-amqp/src/amqp/message_sender.cpp +++ b/sdk/core/azure-core-amqp/src/amqp/message_sender.cpp @@ -123,7 +123,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { // Log that an error occurred. Log::Stream(Logger::Level::Error) << "Message sender link detached: " << error.Condition.ToString() << ": " - << error.Description << std::endl; + << error.Description; // Cache the error we received in the OnDetach notification so we can return it to the user on // the next send which fails. diff --git a/sdk/core/azure-core-amqp/src/amqp/session.cpp b/sdk/core/azure-core-amqp/src/amqp/session.cpp index 40b3ce3e3..826dfe241 100644 --- a/sdk/core/azure-core-amqp/src/amqp/session.cpp +++ b/sdk/core/azure-core-amqp/src/amqp/session.cpp @@ -238,7 +238,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace _detail { } auto accessToken = GetConnection()->GetSecurityToken(audience, context); Log::Stream(Logger::Level::Informational) - << "Authenticate with audience: " << audience << ", token: " << accessToken << std::endl; + << "Authenticate with audience: " << audience << ", token: " << accessToken; m_claimsBasedSecurity->SetTrace(GetConnection()->EnableTrace()); if (!m_cbsOpen) diff --git a/sdk/core/azure-core-amqp/src/network/socket_transport.cpp b/sdk/core/azure-core-amqp/src/network/socket_transport.cpp index 8945e9cba..2f4542339 100644 --- a/sdk/core/azure-core-amqp/src/network/socket_transport.cpp +++ b/sdk/core/azure-core-amqp/src/network/socket_transport.cpp @@ -25,7 +25,7 @@ namespace Azure { namespace Core { namespace Amqp { namespace Network { namespac TransportEvents* eventHandler) { Log::Stream(Logger::Level::Verbose) - << "Create socket transport for host " << host << " port: " << port << std::endl; + << "Create socket transport for host " << host << " port: " << port; SOCKETIO_CONFIG socketConfig{host.c_str(), port, nullptr}; return _detail::TransportImpl::CreateFromXioHandle( diff --git a/sdk/core/azure-core/CHANGELOG.md b/sdk/core/azure-core/CHANGELOG.md index 8318cc097..453889836 100644 --- a/sdk/core/azure-core/CHANGELOG.md +++ b/sdk/core/azure-core/CHANGELOG.md @@ -10,7 +10,7 @@ ### Other Changes -- The default logger now logs all non-error outputs to `stdout` instead of `stderr`. Log level `Error` is still logged to `stderr`. +Empty diagnostic messages will no longer be generated. ## 1.10.0 (2023-06-01) diff --git a/sdk/core/azure-core/README.md b/sdk/core/azure-core/README.md index ce7308a71..e33d517e8 100644 --- a/sdk/core/azure-core/README.md +++ b/sdk/core/azure-core/README.md @@ -117,7 +117,8 @@ int main() Note, the listener callback is executed on the same thread as the operation that triggered the log message. It is recommended implementation due the minimal amount of log message processing on the callback thread. -Where message processing is required, consider implementing in a way that the callback pushes the message string into a thread-safe queue, so that another thread would pick the messages from that queue and handle them. +Where message processing is required, consider implementing in a way that the callback pushes the message +string into a thread-safe queue, so that another thread would pick the messages from that queue and handle them. ## Next steps diff --git a/sdk/core/azure-core/inc/azure/core/internal/diagnostics/log.hpp b/sdk/core/azure-core/inc/azure/core/internal/diagnostics/log.hpp index e983ecf8e..dcedc6113 100644 --- a/sdk/core/azure-core/inc/azure/core/internal/diagnostics/log.hpp +++ b/sdk/core/azure-core/inc/azure/core/internal/diagnostics/log.hpp @@ -50,6 +50,19 @@ namespace Azure { namespace Core { namespace Diagnostics { namespace _internal { LoggerStringBuffer m_stringBuffer; }; + class Stream { + public: + Stream(Logger::Level level) : m_stream(GetStream(level)) {} + ~Stream() { m_stream.flush(); } + Stream(Stream const&) = delete; + Stream& operator=(Stream const&) = delete; + + template std::ostream& operator<<(T val) { return m_stream << val; } + + private: + LoggerStream& m_stream; + }; + static bool ShouldWrite(Logger::Level level) { return g_isLoggingEnabled && level >= g_logLevel; @@ -59,6 +72,8 @@ namespace Azure { namespace Core { namespace Diagnostics { namespace _internal { static void EnableLogging(bool isEnabled); static void SetLogLevel(Logger::Level logLevel); - static LoggerStream& Stream(Logger::Level level); + + private: + static LoggerStream& GetStream(Logger::Level level); }; }}}} // namespace Azure::Core::Diagnostics::_internal diff --git a/sdk/core/azure-core/src/environment_log_level_listener.cpp b/sdk/core/azure-core/src/environment_log_level_listener.cpp index e8fea9492..ef6c78cb2 100644 --- a/sdk/core/azure-core/src/environment_log_level_listener.cpp +++ b/sdk/core/azure-core/src/environment_log_level_listener.cpp @@ -120,15 +120,12 @@ EnvironmentLogLevelListener::GetLogListener() static std::function const consoleLogger = [](auto level, auto message) { - std::ostream* os = &std::cout; - if (level == Logger::Level::Error) - { - os = &std::cerr; - } - *os << '[' - << Azure::DateTime(std::chrono::system_clock::now()) - .ToString(DateTime::DateFormat::Rfc3339, DateTime::TimeFractionFormat::AllDigits) - << "] " << LogLevelToConsoleString(level) << " : " << message; + // Log diagnostics to cerr rather than cout. + std::cerr << '[' + << Azure::DateTime(std::chrono::system_clock::now()) + .ToString( + DateTime::DateFormat::Rfc3339, DateTime::TimeFractionFormat::AllDigits) + << "] " << LogLevelToConsoleString(level) << " : " << message; // If the message ends with a new line, flush the stream otherwise insert a new line to // terminate the message. @@ -138,11 +135,11 @@ EnvironmentLogLevelListener::GetLogListener() // insert unnecessary new lines. if (!message.empty() && message.back() == '\n') { - *os << std::flush; + std::cerr << std::flush; } else { - *os << std::endl; + std::cerr << std::endl; } }; diff --git a/sdk/core/azure-core/src/logger.cpp b/sdk/core/azure-core/src/logger.cpp index 71d6c5276..1a93cd917 100644 --- a/sdk/core/azure-core/src/logger.cpp +++ b/sdk/core/azure-core/src/logger.cpp @@ -32,7 +32,7 @@ inline void Log::SetLogLevel(Logger::Level logLevel) { g_logLevel = logLevel; } void Log::Write(Logger::Level level, std::string const& message) { - if (ShouldWrite(level)) + if (ShouldWrite(level) && !message.empty()) { std::shared_lock loggerLock(g_logListenerMutex); if (g_logListener) @@ -54,21 +54,25 @@ void Logger::SetLevel(Logger::Level level) { Log::SetLogLevel(level); } int Log::LoggerStringBuffer::sync() { + // Note that in the case of the caller inserting std::endl, the buffer will be flushed twice, once + // with the \n terminated string, the second time with an empty string (from the destructor of + // Log::Stream). This depends on the code in Log::Write which discards empty strings. Log::Write(m_level, str()); str(std::string()); return 0; } - +namespace { static Log::LoggerStream g_verboseLogger{Logger::Level::Verbose}; static Log::LoggerStream g_informationalLogger{Logger::Level::Informational}; static Log::LoggerStream g_warningLogger{Logger::Level::Warning}; static Log::LoggerStream g_errorLogger{Logger::Level::Error}; +} // namespace /** Returns a custom ostream implementation with a logger based stream buffer. * @param level The level of the log message. * @return A custom ostream implementation. */ -Log::LoggerStream& Log::Stream(Logger::Level level) +Log::LoggerStream& Log::GetStream(Logger::Level level) { switch (level) { diff --git a/sdk/core/azure-core/test/ut/environment_log_level_listener_test.cpp b/sdk/core/azure-core/test/ut/environment_log_level_listener_test.cpp index 03357e163..4dbaef052 100644 --- a/sdk/core/azure-core/test/ut/environment_log_level_listener_test.cpp +++ b/sdk/core/azure-core/test/ut/environment_log_level_listener_test.cpp @@ -127,7 +127,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerVerbose) SetLogLevel("verbose"); std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -135,7 +135,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerVerbose) listener(Logger::Level::Verbose, "message"); EXPECT_NE(buffer.str().find("DEBUG : message"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerError) @@ -143,7 +143,6 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerError) EnvironmentLogLevelListener::SetInitialized(false); SetLogLevel("verbose"); - // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); @@ -161,9 +160,8 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWarning) EnvironmentLogLevelListener::SetInitialized(false); SetLogLevel("verbose"); - // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -171,7 +169,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWarning) listener(Logger::Level::Warning, "message"); EXPECT_NE(buffer.str().find("WARN : message"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerInformational) @@ -179,9 +177,8 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerInformational) EnvironmentLogLevelListener::SetInitialized(false); SetLogLevel("verbose"); - // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -189,7 +186,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerInformational) listener(Logger::Level::Informational, "message"); EXPECT_NE(buffer.str().find("INFO : message"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerUnknown) @@ -197,9 +194,8 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerUnknown) EnvironmentLogLevelListener::SetInitialized(false); SetLogLevel("verbose"); - // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -207,7 +203,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerUnknown) listener(static_cast(42), "message"); EXPECT_NE(buffer.str().find("????? : message"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } // Verify that the log listener inserts a crlf at the end of the message if none is provided. @@ -218,7 +214,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithNoCrlf) // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -226,7 +222,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithNoCrlf) listener(Logger::Level::Informational, "message"); EXPECT_NE(buffer.str().find("INFO : message\n"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } // Verify that the log listener does not insert a crlf at the end of the message if one is provided. @@ -237,7 +233,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithCrlf) // Error logging goes to cerr, all other logging goes to cout. std::stringstream buffer; - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -246,7 +242,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithCrlf) listener(Logger::Level::Informational, "message\n"); EXPECT_NE(buffer.str().find("INFO : message\n"), std::string::npos); EXPECT_EQ(buffer.str().find("INFO : message\n\n"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } // Verify that the log listener handles empty strings correctly. @@ -257,7 +253,7 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithEmptyString) std::stringstream buffer; // Error logging goes to cerr, all other logging goes to cout. - std::streambuf* old = std::cout.rdbuf(buffer.rdbuf()); + std::streambuf* old = std::cerr.rdbuf(buffer.rdbuf()); auto listener = EnvironmentLogLevelListener::GetLogListener(); @@ -266,5 +262,5 @@ TEST_F(EnvironmentLogLevelListenerTest, GetLogListenerWithEmptyString) listener(Logger::Level::Informational, ""); EXPECT_NE(buffer.str().find("INFO : \n"), std::string::npos); EXPECT_EQ(buffer.str().find("INFO : \n\n"), std::string::npos); - std::cout.rdbuf(old); + std::cerr.rdbuf(old); } diff --git a/sdk/core/azure-core/test/ut/logging_test.cpp b/sdk/core/azure-core/test/ut/logging_test.cpp index 9a033a63c..39953227a 100644 --- a/sdk/core/azure-core/test/ut/logging_test.cpp +++ b/sdk/core/azure-core/test/ut/logging_test.cpp @@ -215,24 +215,20 @@ TEST(Logger, LoggerStream) Logger::SetLevel(Logger::Level::Verbose); { - Log::Stream(Logger::Level::Verbose) << "Verbose" << std::endl; - EXPECT_EQ(message, "Verbose\n"); - Log::Stream(Logger::Level::Informational) << "Informational" << std::endl; - EXPECT_EQ(message, "Informational\n"); + Log::Stream(Logger::Level::Verbose) << "Verbose"; + EXPECT_EQ(message, "Verbose"); + message.clear(); + + Log::Stream(Logger::Level::Informational) << "Informational" << 10; + EXPECT_EQ(message, "Informational10"); message.clear(); Log::Stream(Logger::Level::Warning) << "Warning" << std::endl; EXPECT_EQ(message, "Warning\n"); message.clear(); - Log::Stream(Logger::Level::Error) << "Error" << std::endl; - EXPECT_EQ(message, "Error\n"); - message.clear(); - - Log::Stream(Logger::Level::Verbose) << "Test"; - // std::endl flushes the stream, so we need to manually flush the ostream. - Log::Stream(Logger::Level::Verbose).flush(); - EXPECT_EQ(message, "Test"); + Log::Stream(Logger::Level::Error) << "Error"; + EXPECT_EQ(message, "Error"); message.clear(); } @@ -242,54 +238,54 @@ TEST(Logger, LoggerStream) EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Informational) << "Informational" << std::endl; - EXPECT_EQ(message, "Informational\n"); + Log::Stream(Logger::Level::Informational) << "Informational"; + EXPECT_EQ(message, "Informational"); message.clear(); - Log::Stream(Logger::Level::Warning) << "Warning" << std::endl; - EXPECT_EQ(message, "Warning\n"); + Log::Stream(Logger::Level::Warning) << "Warning"; + EXPECT_EQ(message, "Warning"); message.clear(); - Log::Stream(Logger::Level::Error) << "Error" << std::endl; - EXPECT_EQ(message, "Error\n"); + Log::Stream(Logger::Level::Error) << "Error"; + EXPECT_EQ(message, "Error"); message.clear(); } Logger::SetLevel(Logger::Level::Warning); { - Log::Stream(Logger::Level::Verbose) << "Verbose" << std::endl; + Log::Stream(Logger::Level::Verbose) << "Verbose"; EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Informational) << "Informational" << std::endl; + Log::Stream(Logger::Level::Informational) << "Informational"; EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Warning) << "Warning" << std::endl; - EXPECT_EQ(message, "Warning\n"); + Log::Stream(Logger::Level::Warning) << "Warning"; + EXPECT_EQ(message, "Warning"); message.clear(); - Log::Stream(Logger::Level::Error) << "Error" << std::endl; - EXPECT_EQ(message, "Error\n"); + Log::Stream(Logger::Level::Error) << "Error"; + EXPECT_EQ(message, "Error"); message.clear(); } Logger::SetLevel(Logger::Level::Error); { - Log::Stream(Logger::Level::Verbose) << "Verbose" << std::endl; + Log::Stream(Logger::Level::Verbose) << "Verbose"; EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Informational) << "Informational" << std::endl; + Log::Stream(Logger::Level::Informational) << "Informational"; EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Warning) << "Warning" << std::endl; + Log::Stream(Logger::Level::Warning) << "Warning"; EXPECT_EQ(message, ""); message.clear(); - Log::Stream(Logger::Level::Error) << "Error" << std::endl; - EXPECT_EQ(message, "Error\n"); + Log::Stream(Logger::Level::Error) << "Error"; + EXPECT_EQ(message, "Error"); message.clear(); } }