Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Remove multi-thread synchronization from CRT logger wrapper #2885

Merged
merged 3 commits into from
Mar 19, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -24,34 +24,25 @@ namespace Aws
{
public:
DefaultCRTLogSystem(LogLevel logLevel);
virtual ~DefaultCRTLogSystem();
virtual ~DefaultCRTLogSystem() = default;

DefaultCRTLogSystem(DefaultCRTLogSystem&&) = delete;
DefaultCRTLogSystem(const DefaultCRTLogSystem&) = delete;

/**
* 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<LogLevel> m_logLevel;

// destruction synchronization
mutable std::atomic<bool> m_stopLogging;
mutable std::atomic<size_t> m_logsProcessed;
mutable std::condition_variable m_stopSignal;
mutable std::mutex m_stopMutex;
};

} // namespace Logging
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
5 changes: 5 additions & 0 deletions src/aws-cpp-sdk-core/source/Globals.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
#include <aws/crt/io/TlsOptions.h>
#include <aws/crt/io/Bootstrap.h>
#include <aws/core/Globals.h>
#include <aws/core/utils/logging/LogMacros.h>
#include <aws/core/utils/EnumParseOverflowContainer.h>
#include <aws/core/utils/memory/AWSMemory.h>
#include <aws/auth/auth.h>
Expand Down Expand Up @@ -47,6 +48,10 @@ namespace Aws
void InitializeCrt()
{
g_apiHandle = Aws::New<Aws::Crt::ApiHandle>(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()
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
/**
* Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
* SPDX-License-Identifier: Apache-2.0.
*/

#include <aws/core/utils/logging/CRTLogSystem.h>

using namespace Aws::Utils;
using namespace Aws::Utils::Logging;

namespace Aws
{
namespace Utils
{
namespace Logging
{
static_assert(Aws::Utils::Logging::LogLevel::Off == static_cast<LogLevel>(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<LogLevel>(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<LogLevel>(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<LogLevel>(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<LogLevel>(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<LogLevel>(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<LogLevel>(aws_log_level::AWS_LL_TRACE), "Different underlying values between SDK and CRT log level enums");
}
}
}

117 changes: 40 additions & 77 deletions src/aws-cpp-sdk-core/source/utils/logging/CRTLogging.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -24,11 +24,7 @@ namespace Utils
namespace Logging {

static std::shared_ptr<CRTLogSystemInterface> 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,
Expand All @@ -37,84 +33,57 @@ static int s_aws_logger_redirect_log(
const char *format, ...)
{
AWS_UNREFERENCED_PARAM(logger);
Aws::Utils::Threading::ReaderLockGuard guard(CRTLogSystemLock);
if (CRTLogSystem)
CRTLogSystemInterface* pLogger = CRTLogSystem.get();
if (!pLogger)
{
assert(logger->p_impl == &s_sdkCrtLogger);
Aws::Utils::Logging::LogLevel logLevel = static_cast<LogLevel>(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;
return AWS_OP_ERR;
}
else if (s_CRTLogsRedirectionIsSet)
{
// SDK CRT logger is terminated, fallback to an original/previous CRT logger
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just thought about it more and realized that we don't control / own "original" logger, so better to not try to over-smart ourselves.

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;
}
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<LogLevel>(log_level);
const char* subjectName = aws_log_subject_name(subject);
va_list args;
va_start(args, format);
pLogger->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);
if (CRTLogSystem)
AWS_UNREFERENCED_PARAM(subject);
CRTLogSystemInterface* pLogger = CRTLogSystem.get();
if (pLogger)
{
assert(logger->p_impl == &s_sdkCrtLogger);
return (aws_log_level) (CRTLogSystem->GetLogLevel());
return (aws_log_level) (pLogger->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)
CRTLogSystemInterface* pLogger = CRTLogSystem.get();
if (pLogger)
{
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);
return pLogger->CleanUp();
}
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)
CRTLogSystemInterface* pLogger = CRTLogSystem.get();
if (!pLogger)
{
assert(logger->p_impl == &s_sdkCrtLogger);
CRTLogSystem->SetLogLevel(static_cast<LogLevel>(log_level));
return AWS_OP_SUCCESS;
return AWS_OP_ERR;
}
else if (s_CRTLogsRedirectionIsSet)
{
assert(s_previousCrtLogger.vtable->set_log_level);
return s_previousCrtLogger.vtable->set_log_level(&s_previousCrtLogger, log_level);
}
assert(!"Unreachable state: this method is called without redirection set");
return AWS_OP_ERR;
assert(logger->p_impl == &s_sdkCrtLogger);
pLogger->SetLogLevel(static_cast<LogLevel>(log_level));
return AWS_OP_SUCCESS;

}

static struct aws_logger_vtable s_aws_logger_redirect_vtable = {
Expand All @@ -128,39 +97,33 @@ 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<CRTLogSystemInterface>& inputCrtLogSystem) {
Aws::Utils::Threading::WriterLockGuard g(CRTLogSystemLock);
SetUpCrtLogsRedirection();
CRTLogSystem = inputCrtLogSystem;
}

void ShutdownCRTLogging() {
Aws::Utils::Threading::WriterLockGuard g(CRTLogSystemLock);
CRTLogSystem.reset();
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
auto tmpLogger = std::move(CRTLogSystem);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This approach would not be necessary if the logger's lifetime always exceeded the CRT. We should be able to shutdown the CRT and then call aws_logger_set(nullptr) and have no need for time-based quiesces which are ultimately a flawed approach (someone will always exceed the sleep time). We would then get all the log messages from CRT shutdown. We're shutting down CRT logging before CRT is stopped, and hooking CRT logging in after CRT is started. There's a more fundamental problem here.

std::this_thread::sleep_for(std::chrono::milliseconds(1));
tmpLogger.reset();
}

} // namespace Logging
Expand Down
57 changes: 16 additions & 41 deletions src/aws-cpp-sdk-core/source/utils/logging/DefaultCRTLogSystem.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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;
sbiscigl marked this conversation as resolved.
Show resolved Hide resolved
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<std::mutex> 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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should we set the log level in main SDK logger instead of no-op?

}

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<char> outputBuff(requiredLength);
#ifdef _WIN32
vsnprintf_s(outputBuff.GetUnderlyingData(), requiredLength, _TRUNCATE, formatStr, args);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

exactly the same logic is in the main SDK logger, so just call it instead.

#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<std::mutex> lock(m_stopMutex);
m_stopSignal.notify_all();
pLogSystem->vaLog(logLevel, subjectName, formatStr, args);
}
}
}
Expand Down
Loading
Loading