Core logging infrastructure + logging policy + retry logging (#330)

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
   )
 

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<std::string, std::string> const& GetHeaders() const;
     std::unique_ptr<BodyStream> GetBodyStream()
     {

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 <chrono>
@@ -150,4 +151,24 @@ namespace Azure { namespace Core { namespace Http {
         const override;
   };
 
+  class LoggingPolicy : public HttpPolicy {
+  public:
+    explicit LoggingPolicy() {}
+
+    std::unique_ptr<HttpPolicy> Clone() const override
+    {
+      return std::make_unique<LoggingPolicy>(*this);
+    }
+
+    std::unique_ptr<RawResponse> 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

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

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 <functional>
+#include <initializer_list>
+#include <set>
+#include <string>
+#include <utility>
+
+namespace Azure { namespace Core { namespace Logging {
+  class LogClassification;
+  class LogClassifications;
+
+  typedef std::function<void(LogClassification const& classification, std::string const& message)>
+      LogListener;
+
+  void SetLogListener(LogListener logListener);
+  void SetLogClassifications(LogClassifications logClassifications);
+
+  namespace Details {
+    enum class Facility : uint16_t
+    {
+      Core = 1,
+      Storage = 100,
+    };
+
+    template <Facility> class LogClassificationProvider;
+
+    class LogClassificationsPrivate;
+  } // namespace Details
+
+  class LogClassifications {
+    friend class Details::LogClassificationsPrivate;
+
+    std::set<LogClassification> m_classifications;
+    bool m_all;
+
+    explicit LogClassifications(bool all) : m_all(all) {}
+
+  public:
+    LogClassifications(std::initializer_list<LogClassification> list)
+        : m_classifications(list), m_all(false)
+    {
+    }
+
+    explicit LogClassifications(std::set<LogClassification> set)
+        : m_classifications(std::move(set)), m_all(false)
+    {
+    }
+  };
+
+  class LogClassification {
+    template <Details::Facility> friend class Details::LogClassificationProvider;
+    friend struct std::less<LogClassification>;
+
+    int32_t m_value;
+
+    constexpr explicit LogClassification(Details::Facility facility, int16_t number)
+        : m_value((static_cast<int32_t>(number) << 16) | static_cast<int32_t>(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 <Facility F> class LogClassificationProvider {
+    protected:
+      constexpr static auto Classification(int16_t number) { return LogClassification(F, number); }
+    };
+  } // namespace Details
+}}} // namespace Azure::Core::Logging

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 <http/policy.hpp>
+
+#include <internal/log.hpp>
+
+#include <chrono>
+#include <sstream>
+
+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<std::chrono::milliseconds>(duration).count()
+      << "ms) : " << static_cast<int>(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<RawResponse> 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;
+}

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<RawResponse> NextHttpPolicy::Send(Context& ctx, Request& req)
 {
   if (m_policies == nullptr)
@@ -13,7 +21,7 @@ std::unique_ptr<RawResponse> 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;
   }
 

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<std::string, std::string> const& RawResponse::GetHeaders() const { return this->m_headers; }
 

sdk/core/azure-core/src/http/retry_policy.cpp

@@ -3,11 +3,15 @@
 
 #include <http/policy.hpp>
 
+#include <internal/log.hpp>
+
 #include <algorithm>
 #include <cstdlib>
 #include <limits>
+#include <sstream>
 #include <thread>
 
+using namespace Azure::Core;
 using namespace Azure::Core::Http;
 
 namespace {
@@ -121,11 +125,13 @@ bool ShouldRetryOnResponse(
 }
 } // namespace
 
-std::unique_ptr<RawResponse> RetryPolicy::Send(
+std::unique_ptr<RawResponse> 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<RawResponse> RetryPolicy::Send(
       bodyStream->Rewind();
     }
 
+    if (shouldLog)
+    {
+      std::ostringstream log;
+
+      log << "HTTP Retry attempt #" << attempt << " will be made in "
+          << std::chrono::duration_cast<std::chrono::milliseconds>(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)

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 <mutex>
+
+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<std::mutex> 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<std::mutex> loggerLock(g_loggerMutex);
+  g_logListener = std::move(logListener);
+}
+
+void Azure::Core::Logging::SetLogClassifications(LogClassifications logClassifications)
+{
+  std::lock_guard<std::mutex> 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);
+  }
+}

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

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 <http/pipeline.hpp>
+#include <internal/log.hpp>
+#include <logging/logging.hpp>
+
+#include <utility>
+#include <vector>
+
+using namespace Azure::Core;
+
+namespace {
+typedef std::vector<std::pair<Logging::LogClassification, std::string>> 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);
+}