Logging api - addresses issue #771 (#775)

* Added a basic logger object and relevant macros.

* Modify logging macros for more flexibility.

Supplied logger types and sample values using macros for flexibility in
recompiling the library against a different logging engine - the macros
can be redefined to make calls to the relevant functions.

* Updated endpoint and listener to use new logging structure.

It remains to update the SSL portions of listener.cc to output SSL
errors via the new loggers.

* Add error logging for SSL errors in listener.cc.

This needed an extension to the RAII setup for SSL objects to handle BIO
objects. Also modified some exception types to ensure they get caught
and logged by existing code. Moved anonymous function definitions to the
top of listener.cc so that they are available in the entire file.

These changes don't significantly change the behaviour of the Pistache
library - it still logs errors and throws an exception for most errors
that occur internally. It would likely be more sensible to only throw
a descriptive exception and not log if the exception is expected to be
handled by the library user - this gives them better control of the
output of the software. Logging could be reserved for tracking events
and debug; when the user is not expected to provide input.

* Renamed macros and types to "string logger" and similar.

This aligns the names of the types and macros, as well as leaving space
for future logging APIs that handle different message types.

include/pistache/endpoint.h

@@ -28,6 +28,7 @@ public:
     Options &backlog(int val);
     Options &maxRequestSize(size_t val);
     Options &maxResponseSize(size_t val);
+    Options &logger(PISTACHE_STRING_LOGGER_T logger);
 
     [[deprecated("Replaced by maxRequestSize(val)")]] Options &
     maxPayload(size_t val);
@@ -39,6 +40,7 @@ public:
     int backlog_;
     size_t maxRequestSize_;
     size_t maxResponseSize_;
+    PISTACHE_STRING_LOGGER_T logger_;
     Options();
   };
   Endpoint();
@@ -151,6 +153,7 @@ private:
   Tcp::Listener listener;
   size_t maxRequestSize_ = Const::DefaultMaxRequestSize;
   size_t maxResponseSize_ = Const::DefaultMaxResponseSize;
+  PISTACHE_STRING_LOGGER_T logger_ = PISTACHE_NULL_STRING_LOGGER;
 };
 
 template <typename Handler>

include/pistache/listener.h

@@ -9,6 +9,7 @@
 #include <pistache/async.h>
 #include <pistache/config.h>
 #include <pistache/flags.h>
+#include <pistache/log.h>
 #include <pistache/net.h>
 #include <pistache/os.h>
 #include <pistache/reactor.h>
@@ -51,7 +52,8 @@ public:
   void init(size_t workers,
             Flags<Options> options = Flags<Options>(Options::None),
             const std::string &workersName = "",
-            int backlog = Const::MaxBacklog);
+            int backlog = Const::MaxBacklog,
+            PISTACHE_STRING_LOGGER_T logger = PISTACHE_NULL_STRING_LOGGER);
   void setHandler(const std::shared_ptr<Handler> &handler);
 
   void bind();
@@ -100,6 +102,8 @@ private:
 
   bool useSSL_ = false;
   ssl::SSLCtxPtr ssl_ctx_ = nullptr;
+
+  PISTACHE_STRING_LOGGER_T logger_ = PISTACHE_NULL_STRING_LOGGER;
 };
 
 } // namespace Tcp

include/pistache/log.h

+/* log.h
+   Michael Ellison, 27 May 2020
+
+   Logging API definitions
+*/
+
+#pragma once
+
+#include <memory>
+#include <sstream>
+
+namespace Pistache {
+namespace Log {
+
+enum class Level {
+  TRACE,
+  DEBUG,
+  INFO,
+  WARN,
+  ERROR,
+  FATAL
+};
+
+class StringLogger {
+public:
+  virtual void log(Level level, const std::string &message) = 0;
+  virtual bool isEnabledFor(Level level) const = 0;
+
+  virtual ~StringLogger() {}
+};
+
+class DefaultStringLogger : public StringLogger {
+public:
+  explicit DefaultStringLogger(Level level) : level_(level) {}
+  ~DefaultStringLogger() override {}
+
+  void log(Level level, const std::string &message) override;
+  bool isEnabledFor(Level level) const override;
+private:
+  Level level_;
+};
+
+} // namespace Log
+} // namespace Pistache
+
+#ifndef PISTACHE_LOG_STRING_FATAL
+#define PISTACHE_LOG_STRING_FATAL(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::FATAL)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::FATAL, oss_.str()); \
+  } \
+} while (0)
+#endif
+
+#ifndef PISTACHE_LOG_STRING_ERROR
+#define PISTACHE_LOG_STRING_ERROR(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::ERROR)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::ERROR, oss_.str()); \
+  } \
+} while (0)
+#endif
+
+#ifndef PISTACHE_LOG_STRING_WARN
+#define PISTACHE_LOG_STRING_WARN(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::WARN)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::WARN, oss_.str()); \
+  } \
+} while (0)
+#endif
+
+#ifndef PISTACHE_LOG_STRING_INFO
+#define PISTACHE_LOG_STRING_INFO(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::INFO)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::INFO, oss_.str()); \
+  } \
+} while (0)
+#endif
+
+#ifndef PISTACHE_LOG_STRING_DEBUG
+#define PISTACHE_LOG_STRING_DEBUG(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::DEBUG)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::DEBUG, oss_.str()); \
+  } \
+} while (0)
+#endif
+
+#ifndef PISTACHE_LOG_STRING_TRACE
+#ifndef NDEBUG // Only enable trace logging in debug builds.
+#define PISTACHE_LOG_STRING_TRACE(logger, message) do {\
+  if (logger && logger->isEnabledFor(::Pistache::Log::Level::TRACE)) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::TRACE, oss_.str()); \
+  } \
+} while (0)
+#else
+#define PISTACHE_LOG_STRING_TRACE(logger, message) do {\
+  if (0) { \
+    std::ostringstream oss_; \
+    oss_ << message; \
+    logger->log(::Pistache::Log::Level::TRACE, oss_.str()); \
+  } \
+} while (0)
+#endif
+#endif
+
+#ifndef PISTACHE_STRING_LOGGER_T
+#define PISTACHE_STRING_LOGGER_T \
+  std::shared_ptr<::Pistache::Log::StringLogger>
+#endif
+
+#ifndef PISTACHE_DEFAULT_STRING_LOGGER
+#define PISTACHE_DEFAULT_STRING_LOGGER \
+  std::make_shared<::Pistache::Log::DefaultStringLogger>(::Pistache::Log::Level::WARN)
+#endif
+
+#ifndef PISTACHE_NULL_STRING_LOGGER
+#define PISTACHE_NULL_STRING_LOGGER \
+  nullptr
+#endif
+

include/pistache/ssl_wrappers.h

@@ -26,12 +26,26 @@ struct SSLCtxDeleter {
   }
 };
 
+struct SSLBioDeleter {
+  void operator()(void *ptr) {
+#ifdef PISTACHE_USE_SSL
+    BIO_free(reinterpret_cast<BIO *>(ptr));
+#else
+    (void)ptr;
+#endif
+  }
+};
+
 using SSLCtxPtr = std::unique_ptr<void, SSLCtxDeleter>;
+using SSLBioPtr = std::unique_ptr<void, SSLBioDeleter>;
 
 #ifdef PISTACHE_USE_SSL
 inline SSL_CTX* GetSSLContext(ssl::SSLCtxPtr &ctx) {
     return reinterpret_cast<SSL_CTX *>(ctx.get());
 }
+inline BIO* GetSSLBio(ssl::SSLBioPtr &ctx) {
+    return reinterpret_cast<BIO *>(ctx.get());
+}
 #endif
 
 }

src/common/log.cc

+/* log.cc
+   Michael Ellison, 27 May 2020
+
+   Implementation of the default logger
+*/
+
+#include <iostream>
+
+#include <pistache/log.h>
+
+namespace Pistache {
+namespace Log {
+
+void DefaultStringLogger::log(Level level, const std::string &message) {
+  if (isEnabledFor(level)) {
+    std::cerr << message << std::endl;
+  }
+}
+
+bool DefaultStringLogger::isEnabledFor(Level level) const {
+  return static_cast<int>(level) >= static_cast<int>(level_);
+}
+
+} // namespace Log
+} // namespace Pistache
+
+

src/server/endpoint.cc

@@ -15,7 +15,8 @@ namespace Http {
 Endpoint::Options::Options()
     : threads_(1), flags_(), backlog_(Const::MaxBacklog),
       maxRequestSize_(Const::DefaultMaxRequestSize),
-      maxResponseSize_(Const::DefaultMaxResponseSize) {}
+      maxResponseSize_(Const::DefaultMaxResponseSize),
+      logger_(PISTACHE_NULL_STRING_LOGGER) {}
 
 Endpoint::Options &Endpoint::Options::threads(int val) {
   threads_ = val;
@@ -51,6 +52,11 @@ Endpoint::Options &Endpoint::Options::maxResponseSize(size_t val) {
   return *this;
 }
 
+Endpoint::Options &Endpoint::Options::logger(PISTACHE_STRING_LOGGER_T logger) {
+  logger_ = logger;
+  return *this;
+}
+
 Endpoint::Endpoint() {}
 
 Endpoint::Endpoint(const Address &addr) : listener(addr) {}
@@ -59,6 +65,7 @@ void Endpoint::init(const Endpoint::Options &options) {
   listener.init(options.threads_, options.flags_, options.threadsName_);
   maxRequestSize_ = options.maxRequestSize_;
   maxResponseSize_ = options.maxResponseSize_;
+  logger_ = options.logger_;
 }
 
 void Endpoint::setHandler(const std::shared_ptr<Handler> &handler) {

src/server/listener.cc

@@ -37,6 +37,89 @@
 namespace Pistache {
 namespace Tcp {
 
+#ifdef PISTACHE_USE_SSL
+
+namespace {
+
+std::string ssl_print_errors_to_string() {
+  ssl::SSLBioPtr bio{BIO_new(BIO_s_mem())};
+  ERR_print_errors(GetSSLBio(bio));
+
+  static const int buffer_length = 512;
+
+  bool continue_reading = true;
+  char buffer[buffer_length];
+  std::string result;
+
+  while (continue_reading) {
+    int ret = BIO_gets(GetSSLBio(bio), buffer, buffer_length);
+    switch (ret) {
+      case  0:
+      case -1:
+        // Reached the end of the BIO, or it is unreadable for some reason.
+        continue_reading = false;
+        break;
+      case -2:
+        throw std::logic_error("Trying to call PopStringFromBio on a BIO that "
+                               "does not support the BIO_gets method");
+        break;
+      default:  // >0
+        result.append(buffer);
+        break;
+    }
+  }
+
+  return result;
+}
+
+ssl::SSLCtxPtr ssl_create_context(const std::string &cert,
+                                         const std::string &key,
+                                         bool use_compression) {
+  const SSL_METHOD* method = SSLv23_server_method();
+
+  ssl::SSLCtxPtr ctx{SSL_CTX_new(method)};
+  if (ctx == nullptr) {
+    throw std::runtime_error("Cannot setup SSL context");
+  }
+
+  if (!use_compression) {
+    /* Disable compression to prevent BREACH and CRIME vulnerabilities. */
+    if (!SSL_CTX_set_options(GetSSLContext(ctx), SSL_OP_NO_COMPRESSION)) {
+      std::string err = "SSL error - cannot disable compression: "
+                        + ssl_print_errors_to_string();
+      throw std::runtime_error(err);
+    }
+  }
+
+/* Function introduced in 1.0.2 */
+#if OPENSSL_VERSION_NUMBER >= 0x10002000L
+  SSL_CTX_set_ecdh_auto(GetSSLContext(ctx), 1);
+#endif /* OPENSSL_VERSION_NUMBER */
+
+  if (SSL_CTX_use_certificate_chain_file(GetSSLContext(ctx), cert.c_str()) <= 0) {
+    std::string err = "SSL error - cannot load SSL certificate: "
+                      + ssl_print_errors_to_string();
+    throw std::runtime_error(err);
+  }
+
+  if (SSL_CTX_use_PrivateKey_file(GetSSLContext(ctx), key.c_str(), SSL_FILETYPE_PEM) <= 0) {
+    std::string err = "SSL error - cannot load SSL private key: "
+                      + ssl_print_errors_to_string();
+    throw std::runtime_error(err);
+  }
+
+  if (!SSL_CTX_check_private_key(GetSSLContext(ctx))) {
+    std::string err = "SSL error - Private key does not match certificate public key: "
+                      + ssl_print_errors_to_string();
+    throw std::runtime_error(err);
+  }
+
+  return ctx;
+}
+
+}
+#endif /* PISTACHE_USE_SSL */
+
 void setSocketOptions(Fd fd, Flags<Options> options) {
   if (options.hasFlag(Options::ReuseAddr)) {
     int one = 1;
@@ -88,7 +171,8 @@ Listener::~Listener() {
 }
 
 void Listener::init(size_t workers, Flags<Options> options,
-                    const std::string &workersName, int backlog) {
+                    const std::string &workersName, int backlog,
+                    PISTACHE_STRING_LOGGER_T logger) {
   if (workers > hardware_concurrency()) {
     // Log::warning() << "More workers than available cores"
   }
@@ -98,6 +182,7 @@ void Listener::init(size_t workers, Flags<Options> options,
   useSSL_ = false;
   workers_ = workers;
   workersName_ = workersName;
+  logger_ = logger;
 }
 
 void Listener::setHandler(const std::shared_ptr<Handler> &handler) {
@@ -225,9 +310,9 @@ void Listener::run() {
           try {
             handleNewConnection();
           } catch (SocketError &ex) {
-            std::cerr << "Server: " << ex.what() << std::endl;
+            PISTACHE_LOG_STRING_WARN(logger_, "Socket error: " << ex.what());
           } catch (ServerError &ex) {
-            std::cerr << "Server: " << ex.what() << std::endl;
+            PISTACHE_LOG_STRING_FATAL(logger_, "Server error: " << ex.what());
             throw;
           }
         }
@@ -316,14 +401,18 @@ void Listener::handleNewConnection() {
     SSL *ssl_data = SSL_new(GetSSLContext(ssl_ctx_));
     if (ssl_data == nullptr) {
       close(client_fd);
-      throw std::runtime_error("Cannot create SSL connection");
+      std::string err = "SSL error - cannot create SSL connection: "
+                        + ssl_print_errors_to_string();
+      throw ServerError(err.c_str());
     }
 
     SSL_set_fd(ssl_data, client_fd);
     SSL_set_accept_state(ssl_data);
 
     if (SSL_accept(ssl_data) <= 0) {
-      ERR_print_errors_fp(stderr);
+      std::string err = "SSL connection error: "
+                        + ssl_print_errors_to_string();
+      PISTACHE_LOG_STRING_INFO(logger_, err);
       SSL_free(ssl_data);
       close(client_fd);
       return;
@@ -367,61 +456,17 @@ void Listener::dispatchPeer(const std::shared_ptr<Peer> &peer) {
 
 #ifdef PISTACHE_USE_SSL
 
-namespace {
-
-ssl::SSLCtxPtr ssl_create_context(const std::string &cert,
-                                         const std::string &key,
-                                         bool use_compression) {
-  const SSL_METHOD* method = SSLv23_server_method();
-
-  ssl::SSLCtxPtr ctx{SSL_CTX_new(method)};
-  if (ctx == nullptr) {
-    ERR_print_errors_fp(stderr);
-    throw std::runtime_error("Cannot setup SSL context");
-  }
-
-  if (!use_compression) {
-    /* Disable compression to prevent BREACH and CRIME vulnerabilities. */
-    if (!SSL_CTX_set_options(GetSSLContext(ctx), SSL_OP_NO_COMPRESSION)) {
-      ERR_print_errors_fp(stderr);
-      throw std::runtime_error("Cannot disable compression");
-    }
-  }
-
-/* Function introduced in 1.0.2 */
-#if OPENSSL_VERSION_NUMBER >= 0x10002000L
-  SSL_CTX_set_ecdh_auto(GetSSLContext(ctx), 1);
-#endif /* OPENSSL_VERSION_NUMBER */
-
-  if (SSL_CTX_use_certificate_chain_file(GetSSLContext(ctx), cert.c_str()) <= 0) {
-    ERR_print_errors_fp(stderr);
-    throw std::runtime_error("Cannot load SSL certificate");
-  }
-
-  if (SSL_CTX_use_PrivateKey_file(GetSSLContext(ctx), key.c_str(), SSL_FILETYPE_PEM) <= 0) {
-    ERR_print_errors_fp(stderr);
-    throw std::runtime_error("Cannot load SSL private key");
-  }
-
-  if (!SSL_CTX_check_private_key(GetSSLContext(ctx))) {
-    ERR_print_errors_fp(stderr);
-    throw std::runtime_error(
-        "Private key does not match public key in the certificate");
-  }
-
-  return ctx;
-}
-
-}
-
 void Listener::setupSSLAuth(const std::string &ca_file,
                             const std::string &ca_path,
                             int (*cb)(int, void *) = NULL) {
   const char *__ca_file = NULL;
   const char *__ca_path = NULL;
 
-  if (ssl_ctx_ == nullptr)
-    throw std::runtime_error("SSL Context is not initialized");
+  if (ssl_ctx_ == nullptr) {
+    std::string err = "SSL Context is not initialized";
+    PISTACHE_LOG_STRING_FATAL(logger_, err);
+    throw std::runtime_error(err);
+  }
 
   if (!ca_file.empty())
     __ca_file = ca_file.c_str();
@@ -430,8 +475,10 @@ void Listener::setupSSLAuth(const std::string &ca_file,
 
   if (SSL_CTX_load_verify_locations(GetSSLContext(ssl_ctx_), __ca_file,
                                     __ca_path) <= 0) {
-    ERR_print_errors_fp(stderr);
-    throw std::runtime_error("Cannot verify SSL locations");
+    std::string err = "SSL error - Cannot verify SSL locations: "
+                      + ssl_print_errors_to_string();
+    PISTACHE_LOG_STRING_FATAL(logger_, err);
+    throw std::runtime_error(err);
   }
 
   SSL_CTX_set_verify(GetSSLContext(ssl_ctx_),
@@ -451,7 +498,12 @@ void Listener::setupSSL(const std::string &cert_path,
   SSL_load_error_strings();
   OpenSSL_add_ssl_algorithms();
 
-  ssl_ctx_ = ssl_create_context(cert_path, key_path, use_compression);
+  try {
+    ssl_ctx_ = ssl_create_context(cert_path, key_path, use_compression);
+  } catch (std::exception &e) {
+    PISTACHE_LOG_STRING_FATAL(logger_, e.what());
+    throw;
+  }
   useSSL_ = true;
 }
 

tests/CMakeLists.txt

@@ -34,6 +34,7 @@ pistache_test(stream_test)
 pistache_test(reactor_test)
 pistache_test(threadname_test)
 pistache_test(optional_test)
+pistache_test(logger_test)
 
 if (PISTACHE_USE_SSL)
 

tests/logger_test.cc

+#include <utility>
+#include <vector>
+
+#include <pistache/log.h>
+
+#include "gtest/gtest.h"
+
+using namespace Pistache;
+
+class TestStringLogger : public Log::StringLogger {
+public:
+  void log(Log::Level level, const std::string &message) {
+    messages_.push_back(message);
+    levels_.push_back(level);
+  }
+
+  bool isEnabledFor(Log::Level level) const override {
+    switch(level) {
+      case Log::Level::FATAL:
+      case Log::Level::ERROR:
+      case Log::Level::WARN:
+        return true;
+      case Log::Level::INFO:
+      case Log::Level::DEBUG:
+      case Log::Level::TRACE:
+      default:
+        return false;
+    }
+  }
+
+  TestStringLogger(Log::Level level) : level_(level) {}
+
+  Log::Level level_;
+
+  std::vector<std::string> messages_;
+  std::vector<Log::Level>  levels_;
+};
+
+// Test that isEnabledFor is called when using the PISTACHE_LOG_STRING_* macros.
+TEST(logger_test, macros_guard_by_level) {
+  auto logger_subclass = std::make_shared<TestStringLogger>(Log::Level::WARN);
+  auto& actual_messages = logger_subclass->messages_;
+  auto& actual_levels = logger_subclass->levels_;
+
+  std::shared_ptr<::Pistache::Log::StringLogger> logger = logger_subclass;
+
+  PISTACHE_LOG_STRING_FATAL(logger, "test_message_1_fatal");
+  PISTACHE_LOG_STRING_ERROR(logger, "test_message_2_error");
+  PISTACHE_LOG_STRING_WARN(logger,  "test_message_3_warn");
+  PISTACHE_LOG_STRING_INFO(logger,  "test_message_4_info");
+  PISTACHE_LOG_STRING_DEBUG(logger, "test_message_5_debug");
+  PISTACHE_LOG_STRING_TRACE(logger, "test_message_6_trace");
+
+  std::vector<std::string> expected_messages;
+  expected_messages.push_back("test_message_1_fatal");
+  expected_messages.push_back("test_message_2_error");
+  expected_messages.push_back("test_message_3_warn");
+
+  std::vector<Log::Level> expected_levels;
+  expected_levels.push_back(Log::Level::FATAL);
+  expected_levels.push_back(Log::Level::ERROR);
+  expected_levels.push_back(Log::Level::WARN);
+
+  ASSERT_EQ(actual_messages, expected_messages);
+  ASSERT_EQ(actual_levels, expected_levels);
+}
+
+// Test that the PISTACHE_LOG_STRING_* macros guard against accessing a null logger.
+TEST(logger_test, macros_guard_null_logger) {
+  PISTACHE_STRING_LOGGER_T logger = PISTACHE_NULL_STRING_LOGGER;
+
+  PISTACHE_LOG_STRING_FATAL(logger, "test_message_1_fatal");
+  PISTACHE_LOG_STRING_ERROR(logger, "test_message_2_error");
+  PISTACHE_LOG_STRING_WARN(logger,  "test_message_3_warn");
+  PISTACHE_LOG_STRING_INFO(logger,  "test_message_4_info");
+  PISTACHE_LOG_STRING_DEBUG(logger, "test_message_5_debug");
+  PISTACHE_LOG_STRING_TRACE(logger, "test_message_6_trace");
+
+  // Expect no death from accessing the default logger.
+}
+
+// Test that the PISTACHE_LOG_STRING_* macros access a default logger.
+TEST(logger_test, macros_access_default_logger) {
+  PISTACHE_STRING_LOGGER_T logger = PISTACHE_DEFAULT_STRING_LOGGER;
+
+  PISTACHE_LOG_STRING_FATAL(logger, "test_message_1_fatal");
+  PISTACHE_LOG_STRING_ERROR(logger, "test_message_2_error");
+  PISTACHE_LOG_STRING_WARN(logger,  "test_message_3_warn");
+  PISTACHE_LOG_STRING_INFO(logger,  "test_message_4_info");
+  PISTACHE_LOG_STRING_DEBUG(logger, "test_message_5_debug");
+  PISTACHE_LOG_STRING_TRACE(logger, "test_message_6_trace");
+
+  // Expect no death from using the default handler. The only output of the 
+  // default logger is to stdout, so output cannot be confirmed by gtest.
+}
+