From 4bf1f62ba8ea0a75793854793c2eb2bc62f28fc4 Mon Sep 17 00:00:00 2001 From: Anton Kolesnyk <41349689+antkmsft@users.noreply.github.com> Date: Fri, 31 Jul 2020 16:43:47 -0700 Subject: [PATCH] Core logging infrastructure + logging policy + retry logging (#330) --- sdk/core/azure-core/CMakeLists.txt | 2 + sdk/core/azure-core/inc/http/http.hpp | 2 +- sdk/core/azure-core/inc/http/policy.hpp | 21 ++++ sdk/core/azure-core/inc/internal/log.hpp | 11 ++ sdk/core/azure-core/inc/logging/logging.hpp | 93 +++++++++++++++ .../azure-core/src/http/logging_policy.cpp | 99 ++++++++++++++++ sdk/core/azure-core/src/http/policy.cpp | 10 +- sdk/core/azure-core/src/http/raw_response.cpp | 2 +- sdk/core/azure-core/src/http/retry_policy.cpp | 18 ++- sdk/core/azure-core/src/logging/logging.cpp | 78 ++++++++++++ sdk/core/azure-core/test/ut/CMakeLists.txt | 1 + sdk/core/azure-core/test/ut/logging.cpp | 112 ++++++++++++++++++ 12 files changed, 445 insertions(+), 4 deletions(-) create mode 100644 sdk/core/azure-core/inc/internal/log.hpp create mode 100644 sdk/core/azure-core/inc/logging/logging.hpp create mode 100644 sdk/core/azure-core/src/http/logging_policy.cpp create mode 100644 sdk/core/azure-core/src/logging/logging.cpp create mode 100644 sdk/core/azure-core/test/ut/logging.cpp diff --git a/sdk/core/azure-core/CMakeLists.txt b/sdk/core/azure-core/CMakeLists.txt index 6a71534da..a60aab7fc 100644 --- a/sdk/core/azure-core/CMakeLists.txt +++ b/sdk/core/azure-core/CMakeLists.txt @@ -21,6 +21,7 @@ add_library ( src/credentials/policy/policies.cpp src/http/body_stream.cpp src/http/curl/curl.cpp + src/http/logging_policy.cpp src/http/policy.cpp src/http/request.cpp src/http/raw_response.cpp @@ -29,6 +30,7 @@ add_library ( src/http/telemetry_policy.cpp src/http/url.cpp src/http/winhttp/win_http_transport.cpp + src/logging/logging.cpp src/strings.cpp ) diff --git a/sdk/core/azure-core/inc/http/http.hpp b/sdk/core/azure-core/inc/http/http.hpp index 6034baf29..a14389d08 100644 --- a/sdk/core/azure-core/inc/http/http.hpp +++ b/sdk/core/azure-core/inc/http/http.hpp @@ -345,7 +345,7 @@ namespace Azure { namespace Core { namespace Http { int32_t GetMajorVersion() const { return this->m_majorVersion; } int32_t GetMinorVersion() const { return this->m_minorVersion; } HttpStatusCode GetStatusCode() const; - std::string const& GetReasonPhrase(); + std::string const& GetReasonPhrase() const; std::map const& GetHeaders() const; std::unique_ptr GetBodyStream() { diff --git a/sdk/core/azure-core/inc/http/policy.hpp b/sdk/core/azure-core/inc/http/policy.hpp index 33611c8b8..f93b2fa8b 100644 --- a/sdk/core/azure-core/inc/http/policy.hpp +++ b/sdk/core/azure-core/inc/http/policy.hpp @@ -6,6 +6,7 @@ #include "azure.hpp" #include "context.hpp" #include "http.hpp" +#include "logging/logging.hpp" #include "transport.hpp" #include @@ -150,4 +151,24 @@ namespace Azure { namespace Core { namespace Http { const override; }; + class LoggingPolicy : public HttpPolicy { + public: + explicit LoggingPolicy() {} + + std::unique_ptr Clone() const override + { + return std::make_unique(*this); + } + + std::unique_ptr Send(Context& ctx, Request& request, NextHttpPolicy nextHttpPolicy) + const override; + }; + + class LogClassification : private Azure::Core::Logging::Details::LogClassificationProvider< + Azure::Core::Logging::Details::Facility::Core> { + public: + static constexpr auto const Request = Classification(1); + static constexpr auto const Response = Classification(2); + static constexpr auto const Retry = Classification(3); + }; }}} // namespace Azure::Core::Http diff --git a/sdk/core/azure-core/inc/internal/log.hpp b/sdk/core/azure-core/inc/internal/log.hpp new file mode 100644 index 000000000..c020870c7 --- /dev/null +++ b/sdk/core/azure-core/inc/internal/log.hpp @@ -0,0 +1,11 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// SPDX-License-Identifier: MIT + +#pragma once + +#include "logging/logging.hpp" + +namespace Azure { namespace Core { namespace Logging { namespace Details { + bool ShouldWrite(LogClassification const& classification); + void Write(LogClassification const& classification, std::string const& message); +}}}} // namespace Azure::Core::Logging::Details diff --git a/sdk/core/azure-core/inc/logging/logging.hpp b/sdk/core/azure-core/inc/logging/logging.hpp new file mode 100644 index 000000000..d2d13902d --- /dev/null +++ b/sdk/core/azure-core/inc/logging/logging.hpp @@ -0,0 +1,93 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// SPDX-License-Identifier: MIT + +#pragma once + +#include "azure.hpp" + +#include +#include +#include +#include +#include + +namespace Azure { namespace Core { namespace Logging { + class LogClassification; + class LogClassifications; + + typedef std::function + LogListener; + + void SetLogListener(LogListener logListener); + void SetLogClassifications(LogClassifications logClassifications); + + namespace Details { + enum class Facility : uint16_t + { + Core = 1, + Storage = 100, + }; + + template class LogClassificationProvider; + + class LogClassificationsPrivate; + } // namespace Details + + class LogClassifications { + friend class Details::LogClassificationsPrivate; + + std::set m_classifications; + bool m_all; + + explicit LogClassifications(bool all) : m_all(all) {} + + public: + LogClassifications(std::initializer_list list) + : m_classifications(list), m_all(false) + { + } + + explicit LogClassifications(std::set set) + : m_classifications(std::move(set)), m_all(false) + { + } + }; + + class LogClassification { + template friend class Details::LogClassificationProvider; + friend struct std::less; + + int32_t m_value; + + constexpr explicit LogClassification(Details::Facility facility, int16_t number) + : m_value((static_cast(number) << 16) | static_cast(facility)) + { + } + + constexpr bool operator<(LogClassification const& other) const + { + return m_value < other.m_value; + } + + public: + constexpr bool operator==(LogClassification const& other) const + { + return m_value == other.m_value; + } + + constexpr bool operator!=(LogClassification const& other) const + { + return m_value != other.m_value; + } + + static LogClassifications const All; + static LogClassifications const None; + }; + + namespace Details { + template class LogClassificationProvider { + protected: + constexpr static auto Classification(int16_t number) { return LogClassification(F, number); } + }; + } // namespace Details +}}} // namespace Azure::Core::Logging diff --git a/sdk/core/azure-core/src/http/logging_policy.cpp b/sdk/core/azure-core/src/http/logging_policy.cpp new file mode 100644 index 000000000..ae7a1cec9 --- /dev/null +++ b/sdk/core/azure-core/src/http/logging_policy.cpp @@ -0,0 +1,99 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// SPDX-License-Identifier: MIT + +#include + +#include + +#include +#include + +using namespace Azure::Core; +using namespace Azure::Core::Http; + +namespace { +std::string TruncateIfLengthy(std::string const& s) +{ + static constexpr auto const MaxLength = 50; + + auto const length = s.length(); + if (length <= MaxLength) + { + return s; + } + + static constexpr char const Ellipsis[] = " ... "; + static constexpr auto const EllipsisLength = sizeof(Ellipsis) - 1; + + auto const BeginLength = (MaxLength / 2) - ((EllipsisLength / 2) + (EllipsisLength % 2)); + auto const EndLength = ((MaxLength / 2) + (MaxLength % 2)) - (EllipsisLength / 2); + + return s.substr(0, BeginLength) + Ellipsis + s.substr(length - EndLength, EndLength); +} + +std::string GetRequestLogMessage(Request const& request) +{ + std::ostringstream log; + + log << "HTTP Request : " << HttpMethodToString(request.GetMethod()) << " " + << request.GetEncodedUrl(); + + for (auto header : request.GetHeaders()) + { + log << "\n\t" << header.first << " : " << TruncateIfLengthy(header.second); + } + + return log.str(); +} + +std::string GetResponseLogMessage( + Request const& request, + RawResponse const& response, + std::chrono::system_clock::duration const& duration) +{ + std::ostringstream log; + + log << "HTTP Response (" + << std::chrono::duration_cast(duration).count() + << "ms) : " << static_cast(response.GetStatusCode()) << " " + << response.GetReasonPhrase(); + + for (auto header : response.GetHeaders()) + { + log << "\n\t" << header.first; + if (!header.second.empty() && header.first != "authorization") + { + log << " : " << TruncateIfLengthy(header.second); + } + } + + log << "\n\n -> " << GetRequestLogMessage(request); + + return log.str(); +} +} // namespace + +std::unique_ptr Azure::Core::Http::LoggingPolicy::Send( + Context& ctx, + Request& request, + NextHttpPolicy nextHttpPolicy) const +{ + if (Logging::Details::ShouldWrite(LogClassification::Request)) + { + Logging::Details::Write(LogClassification::Request, GetRequestLogMessage(request)); + } + + if (!Logging::Details::ShouldWrite(LogClassification::Response)) + { + return nextHttpPolicy.Send(ctx, request); + } + + auto const start = std::chrono::system_clock::now(); + auto response = nextHttpPolicy.Send(ctx, request); + auto const end = std::chrono::system_clock::now(); + + Logging::Details::Write( + LogClassification::Response, GetResponseLogMessage(request, *response, end - start)); + + return response; +} diff --git a/sdk/core/azure-core/src/http/policy.cpp b/sdk/core/azure-core/src/http/policy.cpp index d41209e09..f7d3f4710 100644 --- a/sdk/core/azure-core/src/http/policy.cpp +++ b/sdk/core/azure-core/src/http/policy.cpp @@ -6,6 +6,14 @@ using namespace Azure::Core::Http; +#ifndef _MSC_VER +// Non-MSVC compilers do require allocation of statics, even if they are const constexpr. +// MSVC, on the other hand, has problem if you "redefine" static constexprs. +Azure::Core::Logging::LogClassification const Azure::Core::Http::LogClassification::Request; +Azure::Core::Logging::LogClassification const Azure::Core::Http::LogClassification::Response; +Azure::Core::Logging::LogClassification const Azure::Core::Http::LogClassification::Retry; +#endif + std::unique_ptr NextHttpPolicy::Send(Context& ctx, Request& req) { if (m_policies == nullptr) @@ -13,7 +21,7 @@ std::unique_ptr NextHttpPolicy::Send(Context& ctx, Request& req) if (m_index == m_policies->size() - 1) { - //All the policies have run without running a transport policy + // All the policies have run without running a transport policy throw; } diff --git a/sdk/core/azure-core/src/http/raw_response.cpp b/sdk/core/azure-core/src/http/raw_response.cpp index aa7c64b57..d42c0edad 100644 --- a/sdk/core/azure-core/src/http/raw_response.cpp +++ b/sdk/core/azure-core/src/http/raw_response.cpp @@ -14,7 +14,7 @@ using namespace Azure::Core::Http; HttpStatusCode RawResponse::GetStatusCode() const { return m_statusCode; } -std::string const& RawResponse::GetReasonPhrase() { return m_reasonPhrase; } +std::string const& RawResponse::GetReasonPhrase() const { return m_reasonPhrase; } std::map const& RawResponse::GetHeaders() const { return this->m_headers; } diff --git a/sdk/core/azure-core/src/http/retry_policy.cpp b/sdk/core/azure-core/src/http/retry_policy.cpp index 9239110b2..73fb24f13 100644 --- a/sdk/core/azure-core/src/http/retry_policy.cpp +++ b/sdk/core/azure-core/src/http/retry_policy.cpp @@ -3,11 +3,15 @@ #include +#include + #include #include #include +#include #include +using namespace Azure::Core; using namespace Azure::Core::Http; namespace { @@ -121,11 +125,13 @@ bool ShouldRetryOnResponse( } } // namespace -std::unique_ptr RetryPolicy::Send( +std::unique_ptr Azure::Core::Http::RetryPolicy::Send( Context& ctx, Request& request, NextHttpPolicy nextHttpPolicy) const { + auto const shouldLog = Logging::Details::ShouldWrite(LogClassification::Retry); + for (RetryNumber attempt = 1;; ++attempt) { Delay retryAfter{}; @@ -161,6 +167,16 @@ std::unique_ptr RetryPolicy::Send( bodyStream->Rewind(); } + if (shouldLog) + { + std::ostringstream log; + + log << "HTTP Retry attempt #" << attempt << " will be made in " + << std::chrono::duration_cast(retryAfter).count() << "ms."; + + Logging::Details::Write(LogClassification::Retry, log.str()); + } + // Sleep(0) behavior is implementation-defined: it may yield, or may do nothing. Let's make sure // we proceed immediately if it is 0. if (retryAfter.count() > 0) diff --git a/sdk/core/azure-core/src/logging/logging.cpp b/sdk/core/azure-core/src/logging/logging.cpp new file mode 100644 index 000000000..a61400f9c --- /dev/null +++ b/sdk/core/azure-core/src/logging/logging.cpp @@ -0,0 +1,78 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// SPDX-License-Identifier: MIT + +#include "logging/logging.hpp" +#include "internal/log.hpp" + +#include + +using namespace Azure::Core::Logging; +using namespace Azure::Core::Logging::Details; + +class Azure::Core::Logging::Details::LogClassificationsPrivate { +public: + static LogClassifications const LogClassificationsConstant(bool all) + { + return LogClassifications(all); + } + + static bool IsClassificationEnabled(LogClassifications const& cls, LogClassification const& c) + { + return cls.m_all || (cls.m_classifications.find(c) != cls.m_classifications.end()); + } +}; + +namespace { +std::mutex g_loggerMutex; +LogListener g_logListener(nullptr); + +LogClassifications g_logClassifications( + LogClassificationsPrivate::LogClassificationsConstant(true)); + +LogListener GetLogListener(LogClassification const& classification) +{ + // lock listener and classifications + std::lock_guard loggerLock(g_loggerMutex); + + return (!g_logListener // if no logger is set + || LogClassificationsPrivate::IsClassificationEnabled( + g_logClassifications, classification)) + // or if classification is enabled + ? g_logListener // return actual listener (may be null) + : LogListener(nullptr) // return null listener + ; +} +} // namespace + +LogClassifications const Azure::Core::Logging::LogClassification::All( + LogClassificationsPrivate::LogClassificationsConstant(true)); + +LogClassifications const Azure::Core::Logging::LogClassification::None( + LogClassificationsPrivate::LogClassificationsConstant(false)); + +void Azure::Core::Logging::SetLogListener(LogListener logListener) +{ + std::lock_guard loggerLock(g_loggerMutex); + g_logListener = std::move(logListener); +} + +void Azure::Core::Logging::SetLogClassifications(LogClassifications logClassifications) +{ + std::lock_guard loggerLock(g_loggerMutex); + g_logClassifications = std::move(logClassifications); +} + +bool Azure::Core::Logging::Details::ShouldWrite(LogClassification const& classification) +{ + return GetLogListener(classification) != nullptr; +} + +void Azure::Core::Logging::Details::Write( + LogClassification const& classification, + std::string const& message) +{ + if (auto logListener = GetLogListener(classification)) + { + logListener(classification, message); + } +} diff --git a/sdk/core/azure-core/test/ut/CMakeLists.txt b/sdk/core/azure-core/test/ut/CMakeLists.txt index b81a2d483..e1f39dfdd 100644 --- a/sdk/core/azure-core/test/ut/CMakeLists.txt +++ b/sdk/core/azure-core/test/ut/CMakeLists.txt @@ -23,6 +23,7 @@ add_executable ( ${TARGET_NAME} file_upload.cpp http.cpp + logging.cpp main.cpp nullable.cpp string.cpp diff --git a/sdk/core/azure-core/test/ut/logging.cpp b/sdk/core/azure-core/test/ut/logging.cpp new file mode 100644 index 000000000..162b3cb97 --- /dev/null +++ b/sdk/core/azure-core/test/ut/logging.cpp @@ -0,0 +1,112 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// SPDX-License-Identifier: MIT + +#include "gtest/gtest.h" +#include +#include +#include + +#include +#include + +using namespace Azure::Core; + +namespace { +typedef std::vector> LogArguments; + +struct LogRecorder +{ + LogArguments Actual; + + Logging::LogListener LogListener + = [&](Logging::LogClassification const& c, std::string const& m) { + Actual.push_back(std::make_pair(c, m)); + }; +}; +} // namespace + +TEST(Logging, allClassifications) +{ + LogArguments const Values{ + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Response, "Response"}, + {Http::LogClassification::Request, "Request"}, + }; + + LogRecorder logRecorder; + Logging::SetLogListener(logRecorder.LogListener); + + Logging::SetLogClassifications(Logging::LogClassification::All); + auto const expected = Values; + + for (auto value : Values) + { + Logging::Details::Write(value.first, value.second); + } + + EXPECT_EQ(logRecorder.Actual, expected); +} + +TEST(Logging, filteredClassifications) +{ + LogArguments const Values{ + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Response, "Response"}, + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Retry, "Retry"}, + }; + + LogRecorder logRecorder; + Logging::SetLogListener(logRecorder.LogListener); + + auto const AllowedClassification1 = Http::LogClassification::Request; + auto const AllowedClassification2 = Http::LogClassification::Retry; + Logging::SetLogClassifications({AllowedClassification1, AllowedClassification2}); + + LogArguments expected; + for (auto value : Values) + { + if (value.first == AllowedClassification1 || value.first == AllowedClassification2) + { + expected.push_back(value); + } + } + + for (auto value : Values) + { + EXPECT_EQ( + Logging::Details::ShouldWrite(value.first), + (value.first == AllowedClassification1 || value.first == AllowedClassification2)); + + Logging::Details::Write(value.first, value.second); + } + + EXPECT_EQ(logRecorder.Actual, expected); +} + +TEST(Logging, noClassifications) +{ + LogArguments const Values{ + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Request, "Request"}, + {Http::LogClassification::Response, "Response"}, + {Http::LogClassification::Request, "Request"}, + }; + + LogRecorder logRecorder; + Logging::SetLogListener(logRecorder.LogListener); + + auto const AllowedClassification = Http::LogClassification::Request; + Logging::SetLogClassifications(Logging::LogClassification::None); + LogArguments const expected; // Empty + + for (auto value : Values) + { + EXPECT_EQ(Logging::Details::ShouldWrite(value.first), false); + Logging::Details::Write(value.first, value.second); + } + + EXPECT_EQ(logRecorder.Actual, expected); +}