server: Create a mocking infrastructure for logging, by delegating the log-sinks

STYLE.md

@@ -109,6 +109,11 @@ A few general notes on our error handling philosophy:
   that there is complete test coverage for the degraded case.** Additionally, the user should be
   aware of the degraded state minimally via an error log of level warn or greater and via the
   increment of a stat.
+* If you do need to log a non-fatal warning or error, you can unit-test it with EXPECT_LOG_CONTAINS or
+  EXPECT_NO_LOGS from test/test_common/logging.h. It's generally bad practice to test by depending on
+  log messages unless the actual behavior being validated is logging. It's preferable to export
+  statistics to enable consumption by external monitoring for any behavior that should be externally
+  consumed or to introduce appropriate internal interfaces such as mocks for internal behavior.
 * The error handling philosophy described herein is based on the assumption that Envoy is deployed
   using industry best practices (primarily canary). Major and obvious errors should always be
   caught in canary. If a low rate error leads to periodic crash cycling when deployed to

source/common/common/logger.cc

@@ -1,5 +1,6 @@
 #include "common/common/logger.h"
 
+#include <cassert> // use direct system-assert to avoid cyclic dependency.
 #include <cstdint>
 #include <iostream>
 #include <string>
@@ -25,48 +26,81 @@ Logger::Logger(const std::string& name) {
   logger_->flush_on(spdlog::level::critical);
 }
 
-void LockingStderrOrFileSink::logToStdErr() { log_file_.reset(); }
+SinkDelegate::SinkDelegate(DelegatingLogSinkPtr log_sink)
+    : previous_delegate_(log_sink->delegate()), log_sink_(log_sink) {
+  log_sink->setDelegate(this);
+}
 
-void LockingStderrOrFileSink::logToFile(const std::string& log_path,
-                                        AccessLog::AccessLogManager& log_manager) {
-  log_file_ = log_manager.createAccessLog(log_path);
+SinkDelegate::~SinkDelegate() {
+  assert(log_sink_->delegate() == this); // Ensures stacked allocation of delegates.
+  log_sink_->setDelegate(previous_delegate_);
 }
 
-std::vector<Logger>& Registry::allLoggers() {
-  static std::vector<Logger>* all_loggers =
-      new std::vector<Logger>({ALL_LOGGER_IDS(GENERATE_LOGGER)});
-  return *all_loggers;
+FileSinkDelegate::FileSinkDelegate(const std::string& log_path,
+                                   AccessLog::AccessLogManager& log_manager,
+                                   DelegatingLogSinkPtr log_sink)
+    : SinkDelegate(log_sink), log_file_(log_manager.createAccessLog(log_path)) {}
+
+void FileSinkDelegate::log(absl::string_view msg) {
+  // Logfiles have internal locking to ensure serial, non-interleaved
+  // writes, so no additional locking needed here.
+  log_file_->write(msg);
 }
 
-void LockingStderrOrFileSink::log(const spdlog::details::log_msg& msg) {
-  if (log_file_) {
-    // Logfiles have internal locking to ensure serial, non-interleaved
-    // writes, so no additional locking needed here.
-    log_file_->write(msg.formatted.str());
-  } else {
-    Thread::OptionalLockGuard<Thread::BasicLockable> guard(lock_);
-    std::cerr << msg.formatted.str();
-  }
+void FileSinkDelegate::flush() {
+  // Logfiles have internal locking to ensure serial, non-interleaved
+  // writes, so no additional locking needed here.
+  log_file_->flush();
 }
 
-void LockingStderrOrFileSink::flush() {
-  if (log_file_) {
-    // Logfiles have internal locking to ensure serial, non-interleaved
-    // writes, so no additional locking needed here.
-    log_file_->flush();
-  } else {
-    Thread::OptionalLockGuard<Thread::BasicLockable> guard(lock_);
-    std::cerr << std::flush;
-  }
+StderrSinkDelegate::StderrSinkDelegate(DelegatingLogSinkPtr log_sink) : SinkDelegate(log_sink) {}
+
+void StderrSinkDelegate::log(absl::string_view msg) {
+  Thread::OptionalLockGuard<Thread::BasicLockable> guard(lock_);
+  std::cerr << msg;
 }
 
-spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast<int>(id)].logger_; }
+void StderrSinkDelegate::flush() {
+  Thread::OptionalLockGuard<Thread::BasicLockable> guard(lock_);
+  std::cerr << std::flush;
+}
+
+void DelegatingLogSink::log(const spdlog::details::log_msg& msg) {
+  sink_->log(msg.formatted.str());
+}
+
+DelegatingLogSinkPtr DelegatingLogSink::init() {
+  DelegatingLogSinkPtr delegating_sink(new DelegatingLogSink);
+  delegating_sink->stderr_sink_ = std::make_unique<StderrSinkDelegate>(delegating_sink);
+  return delegating_sink;
+}
 
-void Registry::initialize(uint64_t log_level, const std::string& log_format,
+void Registry::initialize(spdlog::level::level_enum log_level, const std::string& log_format,
                           Thread::BasicLockable& lock) {
+  // TODO(jmarantz): I think it would be more robust to push a separate lockable
+  // SinkDelegate onto the stack for the lifetime of the lock, so we don't crash
+  // if we try to log anything after the context owning the lock is destroyed.
   getSink()->setLock(lock);
+  setLogLevel(log_level);
+  setLogFormat(log_format);
+}
+
+std::vector<Logger>& Registry::allLoggers() {
+  static std::vector<Logger>* all_loggers =
+      new std::vector<Logger>({ALL_LOGGER_IDS(GENERATE_LOGGER)});
+  return *all_loggers;
+}
+
+spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast<int>(id)].logger_; }
+
+void Registry::setLogLevel(spdlog::level::level_enum log_level) {
   for (Logger& logger : allLoggers()) {
     logger.logger_->set_level(static_cast<spdlog::level::level_enum>(log_level));
+  }
+}
+
+void Registry::setLogFormat(const std::string& log_format) {
+  for (Logger& logger : allLoggers()) {
     logger.logger_->set_pattern(log_format);
   }
 }

source/common/common/logger.h

@@ -12,6 +12,7 @@
 #include "common/common/fmt.h"
 #include "common/common/macros.h"
 
+#include "absl/strings/string_view.h"
 #include "spdlog/spdlog.h"
 
 namespace Envoy {
@@ -53,10 +54,6 @@ enum class Id {
  */
 class Logger {
 public:
-  std::string levelString() const { return spdlog::level::level_names[logger_->level()]; }
-  std::string name() const { return logger_->name(); }
-  void setLevel(spdlog::level::level_enum level) const { logger_->set_level(level); }
-
   /* This is simple mapping between Logger severity levels and spdlog severity levels.
    * The only reason for this mapping is to go around the fact that spdlog defines level as err
    * but the method to log at err level is called LOGGER.error not LOGGER.err. All other level are
@@ -72,6 +69,11 @@ class Logger {
     off = spdlog::level::off
   } levels;
 
+  std::string levelString() const { return spdlog::level::level_names[logger_->level()]; }
+  std::string name() const { return logger_->name(); }
+  void setLevel(spdlog::level::level_enum level) { logger_->set_level(level); }
+  spdlog::level::level_enum level() const { return logger_->level(); }
+
   static const char* DEFAULT_LOG_FORMAT;
 
 private:
@@ -82,46 +84,99 @@ class Logger {
   friend class Registry;
 };
 
+class DelegatingLogSink;
+typedef std::shared_ptr<DelegatingLogSink> DelegatingLogSinkPtr;
+
 /**
- * An optionally locking stderr or file logging sink.
- *
- * This sink outputs to either stderr or to a file. It shares both implementations (instead of
- * being two separate classes) because we can't setup file logging until after the AccessLogManager
- * is available, but by that time some loggers have cached their logger from the registry already,
- * so we need to be able switch implementations without replacing the object.
+ * Captures a logging sink that can be delegated to for a bounded amount of time.
+ * On destruction, logging is reverted to its previous state. SinkDelegates must
+ * be allocated/freed as a stack.
  */
-class LockingStderrOrFileSink : public spdlog::sinks::sink {
+class SinkDelegate {
 public:
+  explicit SinkDelegate(DelegatingLogSinkPtr log_sink);
+  virtual ~SinkDelegate();
+
+  virtual void log(absl::string_view msg) PURE;
+  virtual void flush() PURE;
+
+protected:
+  SinkDelegate* previous_delegate() { return previous_delegate_; }
+
+private:
+  SinkDelegate* previous_delegate_;
+  DelegatingLogSinkPtr log_sink_;
+};
+
+/**
+ * SinkDelegate that writes log messages to a file.
+ */
+class FileSinkDelegate : public SinkDelegate {
+public:
+  FileSinkDelegate(const std::string& log_path, AccessLog::AccessLogManager& log_manager,
+                   DelegatingLogSinkPtr log_sink);
+
+  // SinkDelegate
+  void log(absl::string_view msg) override;
+  void flush() override;
+
+private:
+  Filesystem::FileSharedPtr log_file_;
+};
+
+/**
+ * SinkDelegate that writes log messages to stderr.
+ */
+class StderrSinkDelegate : public SinkDelegate {
+public:
+  explicit StderrSinkDelegate(DelegatingLogSinkPtr log_sink);
+
+  // SinkDelegate
+  void log(absl::string_view msg) override;
+  void flush() override;
+
+  bool hasLock() const { return lock_ != nullptr; }
   void setLock(Thread::BasicLockable& lock) { lock_ = &lock; }
 
-  /**
-   * Configure this object to log to stderr.
-   *
-   * @note This method is not thread-safe and can only be called when no other threads
-   * are logging.
-   */
-  void logToStdErr();
+private:
+  Thread::BasicLockable* lock_{};
+};
 
-  /**
-   * Configure this object to log to a file.
-   *
-   * @note This method is not thread-safe and can only be called when no other threads
-   * are logging.
-   */
-  void logToFile(const std::string& log_path, AccessLog::AccessLogManager& log_manager);
+/**
+ * Stacks logging sinks, so you can temporarily override the logging mechanism, restoring
+ * the prevoius state when the DelegatingSink is destructed.
+ */
+class DelegatingLogSink : public spdlog::sinks::sink {
+public:
+  void setLock(Thread::BasicLockable& lock) { stderr_sink_->setLock(lock); }
 
   // spdlog::sinks::sink
   void log(const spdlog::details::log_msg& msg) override;
-  void flush() override;
+  void flush() override { sink_->flush(); }
 
   /**
    * @return bool whether a lock has been established.
    */
-  bool hasLock() const { return lock_ != nullptr; }
+  bool hasLock() const { return stderr_sink_->hasLock(); }
+
+  // Constructs a new DelegatingLogSink, sets up the default sink to stderr,
+  // and returns a shared_ptr to it. A shared_ptr is required for sinks used
+  // in spdlog::logger; it would not otherwise be required in Envoy. This method
+  // must own the construction process because StderrSinkDelegate needs access to
+  // the DelegatingLogSinkPtr, not just the DelegatingLogSink*, and that is only
+  // available after construction.
+  static DelegatingLogSinkPtr init();
 
 private:
-  Thread::BasicLockable* lock_{};
-  Filesystem::FileSharedPtr log_file_;
+  friend class SinkDelegate;
+
+  DelegatingLogSink() = default;
+
+  void setDelegate(SinkDelegate* sink) { sink_ = sink; }
+  SinkDelegate* delegate() { return sink_; }
+
+  SinkDelegate* sink_{nullptr};
+  std::unique_ptr<StderrSinkDelegate> stderr_sink_; // Builtin sink to use as a last resort.
 };
 
 /**
@@ -139,21 +194,35 @@ class Registry {
   /**
    * @return the singleton sink to use for all loggers.
    */
-  static std::shared_ptr<LockingStderrOrFileSink> getSink() {
-    static std::shared_ptr<LockingStderrOrFileSink> sink(new LockingStderrOrFileSink());
+  static DelegatingLogSinkPtr getSink() {
+    static DelegatingLogSinkPtr sink = DelegatingLogSink::init();
     return sink;
   }
 
-  /**
-   * Initialize the logging system from server options.
+  /*
+   * Initialize the logging system with the specified lock and log level.
+   * This is equivalalent to setLogLevel, setLogFormat, and setLock, which
+   * can be called individually as well, e.g. to set the log level without
+   * changing the lock or format.
    */
-  static void initialize(uint64_t log_level, const std::string& log_format,
+  static void initialize(spdlog::level::level_enum log_level, const std::string& log_format,
                          Thread::BasicLockable& lock);
 
   /**
-   * @return const std::vector<Logger>& the installed loggers.
+   * Sets the minimum log severity required to print messages.
+   * Messages below this loglevel will be suppressed.
+   */
+  static void setLogLevel(spdlog::level::level_enum log_level);
+
+  /**
+   * Sets the log format.
+   */
+  static void setLogFormat(const std::string& log_format);
+
+  /**
+   * @return std::vector<Logger>& the installed loggers.
    */
-  static const std::vector<Logger>& loggers() { return allLoggers(); }
+  static std::vector<Logger>& loggers() { return allLoggers(); }
 
   /**
    * @Return bool whether the registry has been initialized.
@@ -198,7 +267,9 @@ template <Id id> class Loggable {
 #define ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)                                                        \
   (static_cast<spdlog::level::level_enum>(Envoy::Logger::Logger::LEVEL) >= LOGGER.level())
 
-// Compare levels before invoking logger
+// Compare levels before invoking logger. This is an optimization to avoid
+// executing expressions computing log contents when they would be suppressed.
+// The same filtering will also occur in spdlog::logger.
 #define ENVOY_LOG_COMP_AND_LOG(LOGGER, LEVEL, ...)                                                 \
   do {                                                                                             \
     if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) {                                                     \

source/server/http/admin.cc

@@ -173,13 +173,13 @@ bool AdminImpl::changeLogLevel(const Http::Utility::QueryParams& params) {
   // Now either change all levels or a single level.
   if (name == "level") {
     ENVOY_LOG(debug, "change all log levels: level='{}'", level);
-    for (const Logger::Logger& logger : Logger::Registry::loggers()) {
+    for (Logger::Logger& logger : Logger::Registry::loggers()) {
       logger.setLevel(static_cast<spdlog::level::level_enum>(level_to_use));
     }
   } else {
     ENVOY_LOG(debug, "change log level: name='{}' level='{}'", name, level);
-    const Logger::Logger* logger_to_change = nullptr;
-    for (const Logger::Logger& logger : Logger::Registry::loggers()) {
+    Logger::Logger* logger_to_change = nullptr;
+    for (Logger::Logger& logger : Logger::Registry::loggers()) {
       if (logger.name() == name) {
         logger_to_change = &logger;
         break;
@@ -809,7 +809,7 @@ bool AdminImpl::addHandler(const std::string& prefix, const std::string& help_te
   // make no sense as part of a URL path: ? and :.
   const std::string::size_type pos = prefix.find_first_of("&\"'<>?:");
   if (pos != std::string::npos) {
-    ENVOY_LOG(error, "filter \"{}\" contains invalid character '{}'", prefix[pos]);
+    ENVOY_LOG(error, "filter \"{}\" contains invalid character '{}'", prefix, prefix[pos]);
     return false;
   }
 

source/server/server.cc

@@ -56,7 +56,8 @@ InstanceImpl::InstanceImpl(Options& options, Network::Address::InstanceConstShar
   try {
     if (!options.logPath().empty()) {
       try {
-        Logger::Registry::getSink()->logToFile(options.logPath(), access_log_manager_);
+        file_logger_ = std::make_unique<Logger::FileSinkDelegate>(
+            options.logPath(), access_log_manager_, Logger::Registry::getSink());
       } catch (const EnvoyException& e) {
         throw EnvoyException(
             fmt::format("Failed to open log-file '{}'. e.what(): {}", options.logPath(), e.what()));
@@ -80,7 +81,7 @@ InstanceImpl::~InstanceImpl() {
 
   // Stop logging to file before all the AccessLogManager and its dependencies are
   // destructed to avoid crashing at shutdown.
-  Logger::Registry::getSink()->logToStdErr();
+  file_logger_.reset();
 }
 
 Upstream::ClusterManager& InstanceImpl::clusterManager() { return config_->clusterManager(); }

source/server/server.h

@@ -205,6 +205,7 @@ class InstanceImpl : Logger::Loggable<Logger::Id::main>, public Instance {
   InitManagerImpl init_manager_;
   std::unique_ptr<Server::GuardDog> guard_dog_;
   bool terminated_;
+  std::unique_ptr<Logger::FileSinkDelegate> file_logger_;
 };
 
 } // Server