server: warn on admin mutations, GET requests, add mocking of messages

STYLE.md

@@ -105,6 +105,8 @@ 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 by instantiating a 
+  MockLogSink from test/mocks/common.h.
 * 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,11 +26,53 @@ 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);
+}
+
+SinkDelegate::~SinkDelegate() {
+  assert(log_sink_->delegate() == this); // Ensures stacked allocation of delegates.
+  log_sink_->setDelegate(previous_delegate_);
+}
+
+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::logToFile(const std::string& log_path,
-                                        AccessLog::AccessLogManager& log_manager) {
-  log_file_ = log_manager.createAccessLog(log_path);
+void FileSinkDelegate::flush() {
+  // Logfiles have internal locking to ensure serial, non-interleaved
+  // writes, so no additional locking needed here.
+  log_file_->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;
+}
+
+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;
 }
 
 std::vector<Logger>& Registry::allLoggers() {
@@ -38,35 +81,16 @@ std::vector<Logger>& Registry::allLoggers() {
   return *all_loggers;
 }
 
-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();
-  }
-}
+spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast<int>(id)].logger_; }
 
-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;
+void Registry::setLogLevel(uint64_t log_level) {
+  for (Logger& logger : allLoggers()) {
+    logger.logger_->set_level(static_cast<spdlog::level::level_enum>(log_level));
   }
 }
 
-spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast<int>(id)].logger_; }
-
-void Registry::initialize(uint64_t log_level, const std::string& log_format,
-                          Thread::BasicLockable& lock) {
-  getSink()->setLock(lock);
+void Registry::setLogFormat(const std::string& log_format) {
   for (Logger& logger : allLoggers()) {
-    logger.logger_->set_level(static_cast<spdlog::level::level_enum>(log_level));
     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 {
@@ -82,46 +83,96 @@ 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;
+
+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() {}
+
+  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,16 +190,33 @@ 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.
    */
   static void initialize(uint64_t log_level, const std::string& log_format,
-                         Thread::BasicLockable& lock);
+                         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);
+  }
+
+  /**
+   * Sets the log level.
+   */
+  static void setLogLevel(uint64_t log_level);
+
+  /**
+   * Sets the log format.
+   */
+  static void setLogFormat(const std::string& log_format);
 
   /**
    * @return const std::vector<Logger>& the installed loggers.

source/server/http/admin.cc

@@ -126,9 +126,8 @@ const char AdminHtmlEnd[] = R"(
 
 AdminFilter::AdminFilter(AdminImpl& parent) : parent_(parent) {}
 
-Http::FilterHeadersStatus AdminFilter::decodeHeaders(Http::HeaderMap& response_headers,
-                                                     bool end_stream) {
-  request_headers_ = &response_headers;
+Http::FilterHeadersStatus AdminFilter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) {
+  request_headers_ = &headers;
   if (end_stream) {
     onComplete();
   }
@@ -617,7 +616,7 @@ void AdminFilter::onComplete() {
 
   Buffer::OwnedImpl response;
   Http::HeaderMapPtr header_map{new Http::HeaderMapImpl};
-  Http::Code code = parent_.runCallback(path, *header_map, response);
+  Http::Code code = parent_.runCallback(path, this, *header_map, response);
   header_map->insertStatus().value(std::to_string(enumToInt(code)));
   const auto& headers = Http::Headers::get();
   if (header_map->ContentType() == nullptr) {
@@ -717,7 +716,7 @@ void AdminImpl::createFilterChain(Http::FilterChainFactoryCallbacks& callbacks)
   callbacks.addStreamDecoderFilter(Http::StreamDecoderFilterSharedPtr{new AdminFilter(*this)});
 }
 
-Http::Code AdminImpl::runCallback(absl::string_view path_and_query,
+Http::Code AdminImpl::runCallback(absl::string_view path_and_query, AdminFilter* admin_filter,
                                   Http::HeaderMap& response_headers, Buffer::Instance& response) {
   Http::Code code = Http::Code::OK;
   bool found_handler = false;
@@ -729,6 +728,14 @@ Http::Code AdminImpl::runCallback(absl::string_view path_and_query,
 
   for (const UrlHandler& handler : handlers_) {
     if (path_and_query.compare(0, query_index, handler.prefix_) == 0) {
+      if (handler.mutates_server_state_) {
+        const absl::string_view method =
+            admin_filter->requestHeaders().Method()->value().getStringView();
+        if (method != Http::Headers::get().MethodValues.Post) {
+          ENVOY_LOG(warn, "admin path \"{}\" mutates state, method={} rather than POST",
+                    handler.prefix_, method);
+        }
+      }
       code = handler.handler_(path_and_query, response_headers, response);
       found_handler = true;
       break;

source/server/http/admin.h

@@ -31,6 +31,8 @@
 namespace Envoy {
 namespace Server {
 
+class AdminFilter;
+
 /**
  * Implementation of Server::admin.
  */
@@ -44,8 +46,8 @@ class AdminImpl : public Admin,
             const std::string& address_out_path, Network::Address::InstanceConstSharedPtr address,
             Server::Instance& server, Stats::ScopePtr&& listener_scope);
 
-  Http::Code runCallback(absl::string_view path_and_query, Http::HeaderMap& response_headers,
-                         Buffer::Instance& response);
+  Http::Code runCallback(absl::string_view path_and_query, AdminFilter* admin_filter,
+                         Http::HeaderMap& response_headers, Buffer::Instance& response);
   const Network::Socket& socket() override { return *socket_; }
   Network::Socket& mutable_socket() { return *socket_; }
   Network::ListenerConfig& listener() { return listener_; }
@@ -236,14 +238,15 @@ class AdminFilter : public Http::StreamDecoderFilter, Logger::Loggable<Logger::I
   void onDestroy() override {}
 
   // Http::StreamDecoderFilter
-  Http::FilterHeadersStatus decodeHeaders(Http::HeaderMap& response_headers,
-                                          bool end_stream) override;
+  Http::FilterHeadersStatus decodeHeaders(Http::HeaderMap& headers, bool end_stream) override;
   Http::FilterDataStatus decodeData(Buffer::Instance& data, bool end_stream) override;
   Http::FilterTrailersStatus decodeTrailers(Http::HeaderMap& trailers) override;
   void setDecoderFilterCallbacks(Http::StreamDecoderFilterCallbacks& callbacks) override {
     callbacks_ = &callbacks;
   }
 
+  const Http::HeaderMap& requestHeaders() const { return *request_headers_; }
+
 private:
   /**
    * Called when an admin request has been completely received.

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(nullptr);
 }
 
 Upstream::ClusterManager& InstanceImpl::clusterManager() { return config_->clusterManager(); }

source/server/server.h

@@ -202,6 +202,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