From 6106e962dd20891335cb35d8f8ca1928feb7d0e8 Mon Sep 17 00:00:00 2001 From: SergeyRyabinin Date: Mon, 11 Mar 2024 20:01:58 +0000 Subject: [PATCH 1/3] Remove multi-thread synchronization from CRT logger wrapper --- .../core/utils/logging/DefaultCRTLogSystem.h | 15 +-- .../core/utils/logging/FormattedLogSystem.h | 5 + .../core/utils/logging/LogSystemInterface.h | 4 + .../aws/core/utils/logging/NullLogSystem.h | 8 ++ src/aws-cpp-sdk-core/source/Globals.cpp | 5 + .../utils/logging/CRTLogSystemInterface.cpp | 27 +++++ .../source/utils/logging/CRTLogging.cpp | 101 +++++----------- .../utils/logging/DefaultCRTLogSystem.cpp | 57 +++------ .../utils/logging/FormattedLogSystem.cpp | 111 ++++++++++-------- .../utils/logging/LoggingTest.cpp | 18 --- 10 files changed, 159 insertions(+), 192 deletions(-) create mode 100644 src/aws-cpp-sdk-core/source/utils/logging/CRTLogSystemInterface.cpp diff --git a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/DefaultCRTLogSystem.h b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/DefaultCRTLogSystem.h index 6c506535837..9f78b865b1b 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/DefaultCRTLogSystem.h +++ b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/DefaultCRTLogSystem.h @@ -24,7 +24,7 @@ namespace Aws { public: DefaultCRTLogSystem(LogLevel logLevel); - virtual ~DefaultCRTLogSystem(); + virtual ~DefaultCRTLogSystem() = default; DefaultCRTLogSystem(DefaultCRTLogSystem&&) = delete; DefaultCRTLogSystem(const DefaultCRTLogSystem&) = delete; @@ -32,26 +32,17 @@ namespace Aws /** * Gets the currently configured log level. */ - LogLevel GetLogLevel() const override { return m_logLevel; } + LogLevel GetLogLevel() const override; /** * Set a new log level. This has the immediate effect of changing the log output to the new level. */ - void SetLogLevel(LogLevel logLevel) override { m_logLevel.store(logLevel); } + void SetLogLevel(LogLevel logLevel) override; /** * Handle the logging information from common runtime libraries. * Redirect them to C++ SDK logging system by default. */ virtual void Log(LogLevel logLevel, const char* subjectName, const char* formatStr, va_list args) override; - - protected: - std::atomic m_logLevel; - - // destruction synchronization - mutable std::atomic m_stopLogging; - mutable std::atomic m_logsProcessed; - mutable std::condition_variable m_stopSignal; - mutable std::mutex m_stopMutex; }; } // namespace Logging diff --git a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/FormattedLogSystem.h b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/FormattedLogSystem.h index ea8abd2025c..93b30d4aa50 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/FormattedLogSystem.h +++ b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/FormattedLogSystem.h @@ -45,6 +45,11 @@ namespace Aws */ virtual void Log(LogLevel logLevel, const char* tag, const char* formatStr, ...) override; + /** + * Does a printf style output to ProcessFormattedStatement. Don't use this, it's unsafe. See LogStream + */ + virtual void vaLog(LogLevel logLevel, const char* tag, const char* formatStr, va_list args) override; + /** * Writes the stream to ProcessFormattedStatement. */ diff --git a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/LogSystemInterface.h b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/LogSystemInterface.h index cacd24949b7..dfba96a7bba 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/LogSystemInterface.h +++ b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/LogSystemInterface.h @@ -36,6 +36,10 @@ namespace Aws * Does a printf style output to the output stream. Don't use this, it's unsafe. See LogStream */ virtual void Log(LogLevel logLevel, const char* tag, const char* formatStr, ...) = 0; + /** + * va_list overload for Log, avoid using this as well. + */ + virtual void vaLog(LogLevel logLevel, const char* tag, const char* formatStr, va_list args) = 0; /** * Writes the stream to the output stream. */ diff --git a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/NullLogSystem.h b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/NullLogSystem.h index 28f0ad72e7b..92f82033e20 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/utils/logging/NullLogSystem.h +++ b/src/aws-cpp-sdk-core/include/aws/core/utils/logging/NullLogSystem.h @@ -36,6 +36,14 @@ namespace Aws AWS_UNREFERENCED_PARAM(formatStr); } + virtual void vaLog(LogLevel logLevel, const char* tag, const char* formatStr, va_list args) override + { + AWS_UNREFERENCED_PARAM(logLevel); + AWS_UNREFERENCED_PARAM(tag); + AWS_UNREFERENCED_PARAM(formatStr); + AWS_UNREFERENCED_PARAM(args); + } + virtual void LogStream(LogLevel logLevel, const char* tag, const Aws::OStringStream &messageStream) override { AWS_UNREFERENCED_PARAM(logLevel); diff --git a/src/aws-cpp-sdk-core/source/Globals.cpp b/src/aws-cpp-sdk-core/source/Globals.cpp index 36342a23c32..ce81e0f44ef 100644 --- a/src/aws-cpp-sdk-core/source/Globals.cpp +++ b/src/aws-cpp-sdk-core/source/Globals.cpp @@ -7,6 +7,7 @@ #include #include #include +#include #include #include #include @@ -47,6 +48,10 @@ namespace Aws void InitializeCrt() { g_apiHandle = Aws::New(TAG, Aws::get_aws_allocator()); + AWS_FATAL_ASSERT(g_apiHandle); + auto crtVersion = g_apiHandle->GetCrtVersion(); + AWS_LOGSTREAM_INFO(TAG, "Initialized AWS-CRT-CPP with version " + << crtVersion.major << "." << crtVersion.minor << "." << crtVersion.patch); } void CleanupCrt() diff --git a/src/aws-cpp-sdk-core/source/utils/logging/CRTLogSystemInterface.cpp b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogSystemInterface.cpp new file mode 100644 index 00000000000..80b3d838ef8 --- /dev/null +++ b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogSystemInterface.cpp @@ -0,0 +1,27 @@ +/** + * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. + * SPDX-License-Identifier: Apache-2.0. + */ + +#include + +using namespace Aws::Utils; +using namespace Aws::Utils::Logging; + +namespace Aws +{ + namespace Utils + { + namespace Logging + { + static_assert(Aws::Utils::Logging::LogLevel::Off == static_cast(aws_log_level::AWS_LL_NONE), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Fatal == static_cast(aws_log_level::AWS_LL_FATAL), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Error == static_cast(aws_log_level::AWS_LL_ERROR), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Warn == static_cast(aws_log_level::AWS_LL_WARN), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Info == static_cast(aws_log_level::AWS_LL_INFO), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Debug == static_cast(aws_log_level::AWS_LL_DEBUG), "Different underlying values between SDK and CRT log level enums"); + static_assert(Aws::Utils::Logging::LogLevel::Trace == static_cast(aws_log_level::AWS_LL_TRACE), "Different underlying values between SDK and CRT log level enums"); + } + } +} + diff --git a/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp index f68d3bf5df0..f7fcd429514 100644 --- a/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp +++ b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp @@ -24,11 +24,7 @@ namespace Utils namespace Logging { static std::shared_ptr CRTLogSystem(nullptr); -static Aws::Utils::Threading::ReaderWriterLock CRTLogSystemLock; - -static bool s_CRTLogsRedirectionIsSet(false); static aws_logger s_sdkCrtLogger; -static aws_logger s_previousCrtLogger; static int s_aws_logger_redirect_log( struct aws_logger *logger, @@ -37,84 +33,53 @@ static int s_aws_logger_redirect_log( const char *format, ...) { AWS_UNREFERENCED_PARAM(logger); - Aws::Utils::Threading::ReaderLockGuard guard(CRTLogSystemLock); - if (CRTLogSystem) - { - assert(logger->p_impl == &s_sdkCrtLogger); - Aws::Utils::Logging::LogLevel logLevel = static_cast(log_level); - const char* subjectName = aws_log_subject_name(subject); - va_list args; - va_start(args, format); - CRTLogSystem->Log(logLevel, subjectName, format, args); - va_end(args); - return AWS_OP_SUCCESS; - } - else if (s_CRTLogsRedirectionIsSet) + if (!CRTLogSystem) { - // SDK CRT logger is terminated, fallback to an original/previous CRT logger - assert(s_previousCrtLogger.vtable->log); - va_list args; - va_start(args, format); - auto ret = s_previousCrtLogger.vtable->log(&s_previousCrtLogger, log_level, subject, format, args); - va_end(args); - return ret; + return AWS_OP_ERR; } - assert(!"Unreachable state: this method is called without redirection set"); - return AWS_OP_ERR; + assert(logger->p_impl == &s_sdkCrtLogger); + Aws::Utils::Logging::LogLevel logLevel = static_cast(log_level); + const char* subjectName = aws_log_subject_name(subject); + va_list args; + va_start(args, format); + CRTLogSystem->Log(logLevel, subjectName, format, args); + va_end(args); + return AWS_OP_SUCCESS; } static enum aws_log_level s_aws_logger_redirect_get_log_level(struct aws_logger *logger, aws_log_subject_t subject) { AWS_UNREFERENCED_PARAM(logger); - Aws::Utils::Threading::ReaderLockGuard guard(CRTLogSystemLock); + AWS_UNREFERENCED_PARAM(subject); if (CRTLogSystem) { assert(logger->p_impl == &s_sdkCrtLogger); return (aws_log_level) (CRTLogSystem->GetLogLevel()); } - else if (s_CRTLogsRedirectionIsSet) - { - assert(s_previousCrtLogger.vtable->get_log_level); - return s_previousCrtLogger.vtable->get_log_level(&s_previousCrtLogger, subject); - } - assert(!"Unreachable state: this method is called without redirection set"); return AWS_LL_NONE; } static void s_aws_logger_redirect_clean_up(struct aws_logger *logger) { AWS_UNREFERENCED_PARAM(logger); - Aws::Utils::Threading::ReaderLockGuard guard(CRTLogSystemLock); if (CRTLogSystem) { assert(logger->p_impl == &s_sdkCrtLogger); return CRTLogSystem->CleanUp(); } - else if (s_CRTLogsRedirectionIsSet) - { - assert(s_previousCrtLogger.vtable->clean_up); - return s_previousCrtLogger.vtable->clean_up(&s_previousCrtLogger); - } - assert(!"Unreachable state: this method is called without redirection set"); } static int s_aws_logger_redirect_set_log_level(struct aws_logger *logger, enum aws_log_level log_level) { AWS_UNREFERENCED_PARAM(logger); - Aws::Utils::Threading::ReaderLockGuard guard(CRTLogSystemLock); - if (CRTLogSystem) - { - assert(logger->p_impl == &s_sdkCrtLogger); - CRTLogSystem->SetLogLevel(static_cast(log_level)); - return AWS_OP_SUCCESS; - } - else if (s_CRTLogsRedirectionIsSet) + if (!CRTLogSystem) { - assert(s_previousCrtLogger.vtable->set_log_level); - return s_previousCrtLogger.vtable->set_log_level(&s_previousCrtLogger, log_level); + return AWS_OP_ERR; } - assert(!"Unreachable state: this method is called without redirection set"); - return AWS_OP_ERR; + assert(logger->p_impl == &s_sdkCrtLogger); + CRTLogSystem->SetLogLevel(static_cast(log_level)); + return AWS_OP_SUCCESS; + } static struct aws_logger_vtable s_aws_logger_redirect_vtable = { @@ -128,39 +93,29 @@ static struct aws_logger_vtable s_aws_logger_redirect_vtable = { /** * Installs SDK wrapper over CRT logger. * This wrapper will redirect all CRT logger calls to the set SDK "CRTLogSystem" - * (or back to an original CRT logger if SDK API is terminated). * This method is not thread-safe (as the most other global Init/Shutdown APIs of the SDK). */ void SetUpCrtLogsRedirection() { - if (!s_CRTLogsRedirectionIsSet) - { - static std::once_flag flag; - std::call_once(flag, [&]() - { - s_sdkCrtLogger.vtable = &s_aws_logger_redirect_vtable; - s_sdkCrtLogger.allocator = Aws::get_aws_allocator(); - s_sdkCrtLogger.p_impl = &s_sdkCrtLogger; - - auto pPrevLogger = aws_logger_get(); - if (pPrevLogger) { - s_previousCrtLogger = *pPrevLogger; - } - aws_logger_set(&s_sdkCrtLogger); - s_CRTLogsRedirectionIsSet = true; - }); - } + s_sdkCrtLogger.vtable = &s_aws_logger_redirect_vtable; + s_sdkCrtLogger.allocator = Aws::get_aws_allocator(); + s_sdkCrtLogger.p_impl = &s_sdkCrtLogger; + + aws_logger_set(&s_sdkCrtLogger); } void InitializeCRTLogging(const std::shared_ptr& inputCrtLogSystem) { - Aws::Utils::Threading::WriterLockGuard g(CRTLogSystemLock); SetUpCrtLogsRedirection(); CRTLogSystem = inputCrtLogSystem; } void ShutdownCRTLogging() { - Aws::Utils::Threading::WriterLockGuard g(CRTLogSystemLock); - CRTLogSystem.reset(); + // GetLogSystem returns a raw pointer + // so this is a hack to let all other threads finish their log statement after getting a LogSystem pointer + // otherwise we would need to perform ref-counting on each logging statement + auto tmpLogger = std::move(CRTLogSystem); + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + tmpLogger.reset(); } } // namespace Logging diff --git a/src/aws-cpp-sdk-core/source/utils/logging/DefaultCRTLogSystem.cpp b/src/aws-cpp-sdk-core/source/utils/logging/DefaultCRTLogSystem.cpp index fed7f8b7e61..27f39c2335f 100644 --- a/src/aws-cpp-sdk-core/source/utils/logging/DefaultCRTLogSystem.cpp +++ b/src/aws-cpp-sdk-core/source/utils/logging/DefaultCRTLogSystem.cpp @@ -22,57 +22,32 @@ namespace Aws { namespace Logging { - DefaultCRTLogSystem::DefaultCRTLogSystem(LogLevel logLevel) : - m_logLevel(logLevel), - m_stopLogging(false), - m_logsProcessed(0) + DefaultCRTLogSystem::DefaultCRTLogSystem(LogLevel logLevel) { + AWS_UNREFERENCED_PARAM(logLevel); // will use one from the main SDK logger } - DefaultCRTLogSystem::~DefaultCRTLogSystem() + LogLevel DefaultCRTLogSystem::GetLogLevel() const { - m_stopLogging = true; + LogSystemInterface* pLogSystem = Logging::GetLogSystem(); + if (pLogSystem) + { + return pLogSystem->GetLogLevel(); + } + return Aws::Utils::Logging::LogLevel::Off; + } - // Allow all other threads running Log(...) to return - std::unique_lock lock(m_stopMutex); - m_stopSignal.wait_for(lock, - std::chrono::milliseconds(200), - [&](){ return m_logsProcessed.load() == 0; }); + void DefaultCRTLogSystem::SetLogLevel(LogLevel logLevel) + { + AWS_UNREFERENCED_PARAM(logLevel); // will use one from the main SDK logger } void DefaultCRTLogSystem::Log(LogLevel logLevel, const char* subjectName, const char* formatStr, va_list args) { - if(m_stopLogging) - { - return; - } - m_logsProcessed++; - va_list tmp_args; - va_copy(tmp_args, args); -#ifdef _WIN32 - const int requiredLength = _vscprintf(formatStr, tmp_args) + 1; -#else - const int requiredLength = vsnprintf(nullptr, 0, formatStr, tmp_args) + 1; -#endif - va_end(tmp_args); - - Aws::OStringStream logStream; - if (requiredLength > 1) - { - Array outputBuff(requiredLength); -#ifdef _WIN32 - vsnprintf_s(outputBuff.GetUnderlyingData(), requiredLength, _TRUNCATE, formatStr, args); -#else - vsnprintf(outputBuff.GetUnderlyingData(), requiredLength, formatStr, args); -#endif // _WIN32 - logStream << outputBuff.GetUnderlyingData(); - } - Logging::GetLogSystem()->LogStream(logLevel, subjectName, logStream); - m_logsProcessed--; - if(m_logsProcessed == 0 && m_stopLogging) + LogSystemInterface* pLogSystem = Logging::GetLogSystem(); + if (pLogSystem) { - std::unique_lock lock(m_stopMutex); - m_stopSignal.notify_all(); + pLogSystem->vaLog(logLevel, subjectName, formatStr, args); } } } diff --git a/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp b/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp index 26348b68fe2..ee22b167a5d 100644 --- a/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp +++ b/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp @@ -17,44 +17,51 @@ using namespace Aws::Utils; using namespace Aws::Utils::Logging; -static Aws::String CreateLogPrefixLine(LogLevel logLevel, const char* tag) +static const char* GetLogPrefix(const LogLevel logLevel) { - Aws::StringStream ss; - - switch(logLevel) + switch (logLevel) { - case LogLevel::Error: - ss << "[ERROR] "; + case LogLevel::Off: + assert(!"This should never happen."); break; - + case LogLevel::Error: + return "[ERROR] "; case LogLevel::Fatal: - ss << "[FATAL] "; - break; - + return "[FATAL] "; case LogLevel::Warn: - ss << "[WARN] "; - break; - + return "[WARN] "; case LogLevel::Info: - ss << "[INFO] "; - break; - + return "[INFO] "; case LogLevel::Debug: - ss << "[DEBUG] "; - break; - + return "[DEBUG] "; case LogLevel::Trace: - ss << "[TRACE] "; - break; - - default: - ss << "[UNKOWN] "; - break; + return "[TRACE] "; } + return "[UNKNOWN] "; +} - ss << DateTime::Now().CalculateGmtTimeWithMsPrecision() << " " << tag << " [" << std::this_thread::get_id() << "] "; - - return ss.str(); +static Aws::String CreateLogPrefixLine(LogLevel logLevel, const char* tag, const size_t statementSize = 80) +{ + Aws::String prefix; + static const size_t THREAD_ID_LEN = 16; + static const size_t PREFIX_LEN = sizeof("[UNKNOWN] 2000-01-01 20:00:00.000 [] ") - 1 + THREAD_ID_LEN; + const size_t statementLen = PREFIX_LEN + strlen(tag) + statementSize; + + prefix.reserve(statementLen); + prefix = GetLogPrefix(logLevel); + prefix += DateTime::Now().CalculateGmtTimeWithMsPrecision(); + + prefix += ' '; + prefix += tag; + prefix += " ["; + prefix += [](){ + Aws::StringStream strStr; + strStr << std::this_thread::get_id(); + return strStr.str(); + }(); + prefix += "] "; + + return prefix; } FormattedLogSystem::FormattedLogSystem(LogLevel logLevel) : @@ -64,36 +71,44 @@ FormattedLogSystem::FormattedLogSystem(LogLevel logLevel) : void FormattedLogSystem::Log(LogLevel logLevel, const char* tag, const char* formatStr, ...) { - Aws::StringStream ss; - ss << CreateLogPrefixLine(logLevel, tag); - - std::va_list args; + va_list args; va_start(args, formatStr); + vaLog(logLevel, tag, formatStr, args); + va_end(args); +} +void FormattedLogSystem::vaLog(LogLevel logLevel, const char* tag, const char* formatStr, va_list args) +{ va_list tmp_args; //unfortunately you cannot consume a va_list twice va_copy(tmp_args, args); //so we have to copy it - #ifdef _WIN32 - const int requiredLength = _vscprintf(formatStr, tmp_args) + 1; - #else - const int requiredLength = vsnprintf(nullptr, 0, formatStr, tmp_args) + 1; - #endif +#ifdef _WIN32 + const int requiredLength = _vscprintf(formatStr, tmp_args) + 1; +#else + const int requiredLength = vsnprintf(nullptr, 0, formatStr, tmp_args) + 1; +#endif va_end(tmp_args); - Array outputBuff(requiredLength); - #ifdef _WIN32 - vsnprintf_s(outputBuff.GetUnderlyingData(), requiredLength, _TRUNCATE, formatStr, args); - #else - vsnprintf(outputBuff.GetUnderlyingData(), requiredLength, formatStr, args); - #endif // _WIN32 + Aws::String statement = CreateLogPrefixLine(logLevel, tag, requiredLength); - ss << outputBuff.GetUnderlyingData() << std::endl; - - ProcessFormattedStatement(ss.str()); + const size_t oldStatementSz = statement.size(); + const size_t newStatementSz = oldStatementSz + requiredLength; + // assert(statement.capacity() >= newStatementSz); + // assert(statement.capacity() < 3 * newStatementSz / 2); + statement.resize(newStatementSz); + assert(statement.size() == newStatementSz); +#ifdef _WIN32 + vsnprintf_s(&statement[oldStatementSz], requiredLength, _TRUNCATE, formatStr, args); +#else + vsnprintf(&statement[oldStatementSz], requiredLength, formatStr, args); +#endif // _WIN32 - va_end(args); + statement[newStatementSz - 1] = '\n'; + + ProcessFormattedStatement(std::move(statement)); } void FormattedLogSystem::LogStream(LogLevel logLevel, const char* tag, const Aws::OStringStream &message_stream) { - ProcessFormattedStatement(CreateLogPrefixLine(logLevel, tag) + message_stream.str() + "\n"); + auto message = message_stream.str(); + ProcessFormattedStatement(CreateLogPrefixLine(logLevel, tag, message.size()) + std::move(message) + "\n"); } diff --git a/tests/aws-cpp-sdk-core-tests/utils/logging/LoggingTest.cpp b/tests/aws-cpp-sdk-core-tests/utils/logging/LoggingTest.cpp index 5b430e37a21..dbac82aa427 100644 --- a/tests/aws-cpp-sdk-core-tests/utils/logging/LoggingTest.cpp +++ b/tests/aws-cpp-sdk-core-tests/utils/logging/LoggingTest.cpp @@ -57,23 +57,10 @@ class MockCRTLogSystem : public DefaultCRTLogSystem ~MockCRTLogSystem() { - // make sure that MockCRTLogSystem::m_localLogs is not freed before MockCRTLogSystem::Log finishes - m_stopLogging = true; - - // Allow all other threads running Log(...) to return - std::unique_lock lock(m_stopMutex); - m_stopSignal.wait_for(lock, - std::chrono::milliseconds(200), - [&](){ return m_logsProcessed.load() == 0; }); } void Log(LogLevel logLevel, const char* subjectName, const char* formatStr, va_list args) override { - if (m_stopLogging) - { - return; - } - m_logsProcessed++; va_list tmp_args; va_copy(tmp_args, args); #ifdef _WIN32 @@ -104,11 +91,6 @@ class MockCRTLogSystem : public DefaultCRTLogSystem *m_localLogs << outputBuff.GetUnderlyingData() << std::endl; } Logging::GetLogSystem()->LogStream(logLevel, subjectName, logStream); - m_logsProcessed--; - if(m_logsProcessed == 0 && m_stopLogging) - { - m_stopSignal.notify_all(); - } } private: From b321e052f64fc7a463b2bef4f7d64ea387c9e582 Mon Sep 17 00:00:00 2001 From: SergeyRyabinin Date: Fri, 15 Mar 2024 19:00:56 +0000 Subject: [PATCH 2/3] Write logging timestamp without copying --- .../utils/logging/FormattedLogSystem.cpp | 34 +++++++++++++++++-- 1 file changed, 32 insertions(+), 2 deletions(-) diff --git a/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp b/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp index ee22b167a5d..8c269dc59cc 100644 --- a/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp +++ b/src/aws-cpp-sdk-core/source/utils/logging/FormattedLogSystem.cpp @@ -7,7 +7,7 @@ #include #include -#include +#include #include #include @@ -40,6 +40,36 @@ static const char* GetLogPrefix(const LogLevel logLevel) return "[UNKNOWN] "; } +static void AppendTimeStamp(Aws::String& statement) +{ + static const size_t TS_LEN = sizeof("2000-01-01 00:00:00.000") - 1; + const size_t oldStatementSz = statement.size(); + const size_t newStatementSz = oldStatementSz + TS_LEN; + statement.resize(newStatementSz); + + auto now = std::chrono::system_clock::now(); + std::time_t time = std::chrono::system_clock::to_time_t(now); + struct tm gmtTimeStamp; + Aws::Time::GMTime(&gmtTimeStamp, time); + + auto len = std::strftime(&statement[oldStatementSz], TS_LEN, "%Y-%m-%d %H:%M:%S", &gmtTimeStamp); + if (len) + { + int64_t ms = std::chrono::duration_cast(now.time_since_epoch()).count(); + ms = ms - ms / 1000 * 1000; // calculate the milliseconds as fraction. + statement[oldStatementSz + len++] = '.'; + int divisor = 100; + while(divisor) + { + auto digit = ms / divisor; + statement[oldStatementSz + len++] = char('0' + digit); + ms = ms - divisor * digit; + divisor /= 10; + } + statement[oldStatementSz + len] = '\0'; + } +} + static Aws::String CreateLogPrefixLine(LogLevel logLevel, const char* tag, const size_t statementSize = 80) { Aws::String prefix; @@ -49,7 +79,7 @@ static Aws::String CreateLogPrefixLine(LogLevel logLevel, const char* tag, const prefix.reserve(statementLen); prefix = GetLogPrefix(logLevel); - prefix += DateTime::Now().CalculateGmtTimeWithMsPrecision(); + AppendTimeStamp(prefix); prefix += ' '; prefix += tag; From 7d352c17a5158a1dcf85179e6017a5737e01d200 Mon Sep 17 00:00:00 2001 From: SergeyRyabinin Date: Tue, 19 Mar 2024 03:57:48 +0000 Subject: [PATCH 3/3] Call aws_logger_set on Shutdown; capture static pointer --- .../source/utils/logging/CRTLogging.cpp | 24 ++++++++++++------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp index f7fcd429514..e88ab470a07 100644 --- a/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp +++ b/src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp @@ -33,7 +33,8 @@ static int s_aws_logger_redirect_log( const char *format, ...) { AWS_UNREFERENCED_PARAM(logger); - if (!CRTLogSystem) + CRTLogSystemInterface* pLogger = CRTLogSystem.get(); + if (!pLogger) { return AWS_OP_ERR; } @@ -42,7 +43,7 @@ static int s_aws_logger_redirect_log( const char* subjectName = aws_log_subject_name(subject); va_list args; va_start(args, format); - CRTLogSystem->Log(logLevel, subjectName, format, args); + pLogger->Log(logLevel, subjectName, format, args); va_end(args); return AWS_OP_SUCCESS; } @@ -51,10 +52,11 @@ static enum aws_log_level s_aws_logger_redirect_get_log_level(struct aws_logger { AWS_UNREFERENCED_PARAM(logger); AWS_UNREFERENCED_PARAM(subject); - if (CRTLogSystem) + CRTLogSystemInterface* pLogger = CRTLogSystem.get(); + if (pLogger) { assert(logger->p_impl == &s_sdkCrtLogger); - return (aws_log_level) (CRTLogSystem->GetLogLevel()); + return (aws_log_level) (pLogger->GetLogLevel()); } return AWS_LL_NONE; } @@ -62,22 +64,24 @@ static enum aws_log_level s_aws_logger_redirect_get_log_level(struct aws_logger static void s_aws_logger_redirect_clean_up(struct aws_logger *logger) { AWS_UNREFERENCED_PARAM(logger); - if (CRTLogSystem) + CRTLogSystemInterface* pLogger = CRTLogSystem.get(); + if (pLogger) { assert(logger->p_impl == &s_sdkCrtLogger); - return CRTLogSystem->CleanUp(); + return pLogger->CleanUp(); } } static int s_aws_logger_redirect_set_log_level(struct aws_logger *logger, enum aws_log_level log_level) { AWS_UNREFERENCED_PARAM(logger); - if (!CRTLogSystem) + CRTLogSystemInterface* pLogger = CRTLogSystem.get(); + if (!pLogger) { return AWS_OP_ERR; } assert(logger->p_impl == &s_sdkCrtLogger); - CRTLogSystem->SetLogLevel(static_cast(log_level)); + pLogger->SetLogLevel(static_cast(log_level)); return AWS_OP_SUCCESS; } @@ -110,6 +114,10 @@ void InitializeCRTLogging(const std::shared_ptr& inputCrt } void ShutdownCRTLogging() { + if (aws_logger_get() == &s_sdkCrtLogger) + { + aws_logger_set(nullptr); + } // GetLogSystem returns a raw pointer // so this is a hack to let all other threads finish their log statement after getting a LogSystem pointer // otherwise we would need to perform ref-counting on each logging statement