logging: fix delegating log sink races (envoyproxy#12298)

This fixes two different issues:
1) Previously there was no locking around log sink replacement,
   so it was possibles for a log sink to get removed by one
   thread while getting written to by another thread.
2) Even with locking, the base class destructor pattern would
   do the swap after the derived class was destroyed, leading to
   undefined behavior.

This was easy to reproduce in cx_limit_integration_test but is
an issue anywhere the log expectations are used, or previously in the death test
stderr workaround (EXPECT_DEATH_LOG_TO_STDERR) for coverage which has 
been removed because coverage no longer logs to a file and instead logs to stderr
like the rest of the tests.

Fixes envoyproxy#11841

Risk Level: Medium, code is a bit scary, though only really in tests
Testing: Existing tests
Docs Changes: N/A
Release Notes: N/A

Signed-off-by: Matt Klein <[email protected]>

Author: mattklein123

source/common/common/logger.cc

@@ -19,18 +19,34 @@ namespace Logger {
 StandardLogger::StandardLogger(const std::string& name)
     : Logger(std::make_shared<spdlog::logger>(name, Registry::getSink())) {}
 
-SinkDelegate::SinkDelegate(DelegatingLogSinkSharedPtr log_sink)
-    : previous_delegate_(log_sink->delegate()), log_sink_(log_sink) {
-  log_sink->setDelegate(this);
-}
+SinkDelegate::SinkDelegate(DelegatingLogSinkSharedPtr log_sink) : log_sink_(log_sink) {}
 
 SinkDelegate::~SinkDelegate() {
-  assert(log_sink_->delegate() == this); // Ensures stacked allocation of delegates.
+  // The previous delegate should have never been set or should have been reset by now via
+  // restoreDelegate();
+  assert(previous_delegate_ == nullptr);
+}
+
+void SinkDelegate::setDelegate() {
+  // There should be no previous delegate before this call.
+  assert(previous_delegate_ == nullptr);
+  previous_delegate_ = log_sink_->delegate();
+  log_sink_->setDelegate(this);
+}
+
+void SinkDelegate::restoreDelegate() {
+  // Ensures stacked allocation of delegates.
+  assert(log_sink_->delegate() == this);
   log_sink_->setDelegate(previous_delegate_);
+  previous_delegate_ = nullptr;
 }
 
 StderrSinkDelegate::StderrSinkDelegate(DelegatingLogSinkSharedPtr log_sink)
-    : SinkDelegate(log_sink) {}
+    : SinkDelegate(log_sink) {
+  setDelegate();
+}
+
+StderrSinkDelegate::~StderrSinkDelegate() { restoreDelegate(); }
 
 void StderrSinkDelegate::log(absl::string_view msg) {
   Thread::OptionalLockGuard guard(lock_);
@@ -60,6 +76,13 @@ void DelegatingLogSink::log(const spdlog::details::log_msg& msg) {
   }
   lock.Release();
 
+  // Hold the sink mutex while performing the actual logging. This prevents the sink from being
+  // swapped during an individual log event.
+  // TODO(mattklein123): In production this lock will never be contended. In practice, thread
+  // protection is really only needed in tests. It would be nice to figure out a test-only
+  // mechanism for this that does not require extra locking that we don't explicitly need in the
+  // prod code.
+  absl::ReaderMutexLock sink_lock(&sink_mutex_);
   if (should_escape_) {
     sink_->log(escapeLogLine(msg_view));
   } else {

source/common/common/logger.h

@@ -104,10 +104,21 @@ class SinkDelegate : NonCopyable {
   virtual void flush() PURE;
 
 protected:
+  // Swap the current log sink delegate for this one. This should be called by the derived class
+  // constructor immediately before returning. This is required to match restoreDelegate(),
+  // otherwise it's possible for the previous delegate to get set in the base class constructor,
+  // the derived class constructor throws, and cleanup becomes broken.
+  void setDelegate();
+
+  // Swap the current log sink (this) for the previous one. This should be called by the derived
+  // class destructor in the body. This is critical as otherwise it's possible for a log message
+  // to get routed to a partially destructed sink.
+  void restoreDelegate();
+
   SinkDelegate* previousDelegate() { return previous_delegate_; }
 
 private:
-  SinkDelegate* previous_delegate_;
+  SinkDelegate* previous_delegate_{nullptr};
   DelegatingLogSinkSharedPtr log_sink_;
 };
 
@@ -117,6 +128,7 @@ class SinkDelegate : NonCopyable {
 class StderrSinkDelegate : public SinkDelegate {
 public:
   explicit StderrSinkDelegate(DelegatingLogSinkSharedPtr log_sink);
+  ~StderrSinkDelegate() override;
 
   // SinkDelegate
   void log(absl::string_view msg) override;
@@ -141,7 +153,10 @@ class DelegatingLogSink : public spdlog::sinks::sink {
 
   // spdlog::sinks::sink
   void log(const spdlog::details::log_msg& msg) override;
-  void flush() override { sink_->flush(); }
+  void flush() override {
+    absl::ReaderMutexLock lock(&sink_mutex_);
+    sink_->flush();
+  }
   void set_pattern(const std::string& pattern) override {
     set_formatter(spdlog::details::make_unique<spdlog::pattern_formatter>(pattern));
   }
@@ -180,13 +195,20 @@ class DelegatingLogSink : public spdlog::sinks::sink {
 
   DelegatingLogSink() = default;
 
-  void setDelegate(SinkDelegate* sink) { sink_ = sink; }
-  SinkDelegate* delegate() { return sink_; }
+  void setDelegate(SinkDelegate* sink) {
+    absl::WriterMutexLock lock(&sink_mutex_);
+    sink_ = sink;
+  }
+  SinkDelegate* delegate() {
+    absl::ReaderMutexLock lock(&sink_mutex_);
+    return sink_;
+  }
 
-  SinkDelegate* sink_{nullptr};
+  SinkDelegate* sink_ ABSL_GUARDED_BY(sink_mutex_){nullptr};
+  absl::Mutex sink_mutex_;
   std::unique_ptr<StderrSinkDelegate> stderr_sink_; // Builtin sink to use as a last resort.
   std::unique_ptr<spdlog::formatter> formatter_ ABSL_GUARDED_BY(format_mutex_);
-  absl::Mutex format_mutex_; // direct absl reference to break build cycle.
+  absl::Mutex format_mutex_;
   bool should_escape_{false};
 };
 

source/common/common/logger_delegates.cc

@@ -13,7 +13,11 @@ namespace Logger {
 FileSinkDelegate::FileSinkDelegate(const std::string& log_path,
                                    AccessLog::AccessLogManager& log_manager,
                                    DelegatingLogSinkSharedPtr log_sink)
-    : SinkDelegate(log_sink), log_file_(log_manager.createAccessLog(log_path)) {}
+    : SinkDelegate(log_sink), log_file_(log_manager.createAccessLog(log_path)) {
+  setDelegate();
+}
+
+FileSinkDelegate::~FileSinkDelegate() { restoreDelegate(); }
 
 void FileSinkDelegate::log(absl::string_view msg) {
   // Log files have internal locking to ensure serial, non-interleaved

source/common/common/logger_delegates.h

@@ -14,16 +14,14 @@
 namespace Envoy {
 namespace Logger {
 
-class DelegatingLogSink;
-using DelegatingLogSinkSharedPtr = std::shared_ptr<DelegatingLogSink>;
-
 /**
  * SinkDelegate that writes log messages to a file.
  */
 class FileSinkDelegate : public SinkDelegate {
 public:
   FileSinkDelegate(const std::string& log_path, AccessLog::AccessLogManager& log_manager,
                    DelegatingLogSinkSharedPtr log_sink);
+  ~FileSinkDelegate() override;
 
   // SinkDelegate
   void log(absl::string_view msg) override;

test/common/buffer/owned_impl_test.cc

@@ -1034,7 +1034,6 @@ TEST_F(OwnedImplTest, ReadReserveAndCommit) {
 }
 
 TEST(OverflowDetectingUInt64, Arithmetic) {
-  Logger::StderrSinkDelegate stderr_sink(Logger::Registry::getSink()); // For coverage build.
   OverflowDetectingUInt64 length;
   length += 1;
   length -= 1;

test/common/common/assert_test.cc

@@ -7,7 +7,6 @@
 namespace Envoy {
 
 TEST(ReleaseAssertDeathTest, VariousLogs) {
-  Logger::StderrSinkDelegate stderr_sink(Logger::Registry::getSink()); // For coverage build.
   EXPECT_DEATH({ RELEASE_ASSERT(0, ""); }, ".*assert failure: 0.*");
   EXPECT_DEATH({ RELEASE_ASSERT(0, "With some logs"); },
                ".*assert failure: 0. Details: With some logs.*");

test/common/common/logger_test.cc

@@ -8,38 +8,40 @@
 namespace Envoy {
 namespace Logger {
 
-class LoggerEscapeTest : public testing::Test {};
+TEST(LoggerTest, StackingStderrSinkDelegate) {
+  StderrSinkDelegate stacked(Envoy::Logger::Registry::getSink());
+}
 
-TEST_F(LoggerEscapeTest, LinuxEOL) {
+TEST(LoggerEscapeTest, LinuxEOL) {
   EXPECT_EQ("line 1 \\n line 2\n", DelegatingLogSink::escapeLogLine("line 1 \n line 2\n"));
 }
 
-TEST_F(LoggerEscapeTest, WindowEOL) {
+TEST(LoggerEscapeTest, WindowEOL) {
   EXPECT_EQ("line 1 \\n line 2\r\n", DelegatingLogSink::escapeLogLine("line 1 \n line 2\r\n"));
 }
 
-TEST_F(LoggerEscapeTest, NoTrailingWhitespace) {
+TEST(LoggerEscapeTest, NoTrailingWhitespace) {
   EXPECT_EQ("line 1 \\n line 2", DelegatingLogSink::escapeLogLine("line 1 \n line 2"));
 }
 
-TEST_F(LoggerEscapeTest, NoWhitespace) {
+TEST(LoggerEscapeTest, NoWhitespace) {
   EXPECT_EQ("line1", DelegatingLogSink::escapeLogLine("line1"));
 }
 
-TEST_F(LoggerEscapeTest, AnyTrailingWhitespace) {
+TEST(LoggerEscapeTest, AnyTrailingWhitespace) {
   EXPECT_EQ("line 1 \\t tab 1 \\n line 2\t\n",
             DelegatingLogSink::escapeLogLine("line 1 \t tab 1 \n line 2\t\n"));
 }
 
-TEST_F(LoggerEscapeTest, WhitespaceOnly) {
+TEST(LoggerEscapeTest, WhitespaceOnly) {
   // 8 spaces
   EXPECT_EQ("        ", DelegatingLogSink::escapeLogLine("        "));
 
   // Any whitespace characters
   EXPECT_EQ("\r\n\t \r\n \n", DelegatingLogSink::escapeLogLine("\r\n\t \r\n \n"));
 }
 
-TEST_F(LoggerEscapeTest, Empty) { EXPECT_EQ("", DelegatingLogSink::escapeLogLine("")); }
+TEST(LoggerEscapeTest, Empty) { EXPECT_EQ("", DelegatingLogSink::escapeLogLine("")); }
 
 } // namespace Logger
 } // namespace Envoy

test/common/http/header_map_impl_test.cc

@@ -1005,14 +1005,14 @@ TEST(HeaderMapImplTest, TestAppendHeader) {
 TEST(TestHeaderMapImplDeathTest, TestHeaderLengthChecks) {
   HeaderString value;
   value.setCopy("some;");
-  EXPECT_DEATH_LOG_TO_STDERR(value.append(nullptr, std::numeric_limits<uint32_t>::max()),
-                             "Trying to allocate overly large headers.");
+  EXPECT_DEATH(value.append(nullptr, std::numeric_limits<uint32_t>::max()),
+               "Trying to allocate overly large headers.");
 
   std::string source("hello");
   HeaderString reference;
   reference.setReference(source);
-  EXPECT_DEATH_LOG_TO_STDERR(reference.append(nullptr, std::numeric_limits<uint32_t>::max()),
-                             "Trying to allocate overly large headers.");
+  EXPECT_DEATH(reference.append(nullptr, std::numeric_limits<uint32_t>::max()),
+               "Trying to allocate overly large headers.");
 }
 
 TEST(HeaderMapImplTest, PseudoHeaderOrder) {

test/common/http/http2/metadata_encoder_decoder_test.cc

@@ -333,7 +333,6 @@ using MetadataEncoderDecoderDeathTest = MetadataEncoderDecoderTest;
 
 // Crash if a caller tries to pack more frames than the encoder has data for.
 TEST_F(MetadataEncoderDecoderDeathTest, PackTooManyFrames) {
-  Logger::StderrSinkDelegate stderr_sink(Logger::Registry::getSink()); // For coverage build.
   MetadataMap metadata_map = {
       {"header_key1", std::string(5, 'a')},
       {"header_key2", std::string(5, 'b')},

test/common/network/address_impl_test.cc

@@ -448,9 +448,9 @@ TEST(AddressFromSockAddrDeathTest, IPv4) {
   EXPECT_EQ(1, inet_pton(AF_INET, "1.2.3.4", &sin.sin_addr));
   sin.sin_port = htons(6502);
 
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, 1), "ss_len");
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, sizeof(sockaddr_in) - 1), "ss_len");
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, sizeof(sockaddr_in) + 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, sizeof(sockaddr_in) - 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, sizeof(sockaddr_in) + 1), "ss_len");
 
   EXPECT_EQ("1.2.3.4:6502", addressFromSockAddr(ss, sizeof(sockaddr_in))->asString());
 
@@ -467,9 +467,9 @@ TEST(AddressFromSockAddrDeathTest, IPv6) {
   EXPECT_EQ(1, inet_pton(AF_INET6, "01:023::00Ef", &sin6.sin6_addr));
   sin6.sin6_port = htons(32000);
 
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, 1), "ss_len");
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, sizeof(sockaddr_in6) - 1), "ss_len");
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, sizeof(sockaddr_in6) + 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, sizeof(sockaddr_in6) - 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, sizeof(sockaddr_in6) + 1), "ss_len");
 
   EXPECT_EQ("[1:23::ef]:32000", addressFromSockAddr(ss, sizeof(sockaddr_in6))->asString());
 
@@ -490,9 +490,8 @@ TEST(AddressFromSockAddrDeathTest, Pipe) {
 
   StringUtil::strlcpy(sun.sun_path, "/some/path", sizeof sun.sun_path);
 
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, 1), "ss_len");
-  EXPECT_DEATH_LOG_TO_STDERR(addressFromSockAddr(ss, offsetof(struct sockaddr_un, sun_path)),
-                             "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, 1), "ss_len");
+  EXPECT_DEATH(addressFromSockAddr(ss, offsetof(struct sockaddr_un, sun_path)), "ss_len");
 
   socklen_t ss_len = offsetof(struct sockaddr_un, sun_path) + 1 + strlen(sun.sun_path);
   EXPECT_EQ("/some/path", addressFromSockAddr(ss, ss_len)->asString());

test/common/network/connection_impl_test.cc

@@ -85,7 +85,7 @@ TEST_P(ConnectionImplDeathTest, BadFd) {
   Event::DispatcherPtr dispatcher(api->allocateDispatcher("test_thread"));
   IoHandlePtr io_handle = std::make_unique<IoSocketHandleImpl>();
   StreamInfo::StreamInfoImpl stream_info(dispatcher->timeSource());
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       ConnectionImpl(*dispatcher,
                      std::make_unique<ConnectionSocketImpl>(std::move(io_handle), nullptr, nullptr),
                      Network::Test::createRawBufferSocket(), stream_info, false),

test/common/network/listener_impl_test.cc

@@ -59,7 +59,7 @@ INSTANTIATE_TEST_SUITE_P(IpVersions, ListenerImplDeathTest,
                          testing::ValuesIn(TestEnvironment::getIpVersionsForTest()),
                          TestUtility::ipTestParamsToString);
 TEST_P(ListenerImplDeathTest, ErrorCallback) {
-  EXPECT_DEATH_LOG_TO_STDERR(errorCallbackTest(GetParam()), ".*listener accept failure.*");
+  EXPECT_DEATH(errorCallbackTest(GetParam()), ".*listener accept failure.*");
 }
 
 class TestListenerImpl : public ListenerImpl {

test/common/network/udp_listener_impl_test.cc

@@ -390,7 +390,6 @@ TEST_P(UdpListenerImplTest, SendData) {
  * The send fails because the server_socket is created with bind=false.
  */
 TEST_P(UdpListenerImplTest, SendDataError) {
-  Logger::StderrSinkDelegate stderr_sink(Logger::Registry::getSink()); // For coverage build.
   const std::string payload("hello world");
   Buffer::InstancePtr buffer(new Buffer::OwnedImpl());
   buffer->add(payload);

test/common/signal/signals_test.cc

@@ -26,10 +26,11 @@ namespace Envoy {
 #ifndef ASANITIZED
 TEST(SignalsDeathTest, InvalidAddressDeathTest) {
   SignalAction actions;
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       []() -> void {
         // Oops!
         volatile int* nasty_ptr = reinterpret_cast<int*>(0x0);
+        // NOLINTNEXTLINE(clang-analyzer-core.NullDereference)
         *(nasty_ptr) = 0;
       }(),
       "backtrace.*Segmentation fault");
@@ -44,10 +45,11 @@ TEST(SignalsDeathTest, RegisteredHandlerTest) {
   SignalAction::registerFatalErrorHandler(handler);
   SignalAction actions;
   // Make sure the fatal error log "HERE" registered above is logged on fatal error.
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       []() -> void {
         // Oops!
         volatile int* nasty_ptr = reinterpret_cast<int*>(0x0);
+        // NOLINTNEXTLINE(clang-analyzer-core.NullDereference)
         *(nasty_ptr) = 0;
       }(),
       "HERE");
@@ -56,7 +58,7 @@ TEST(SignalsDeathTest, RegisteredHandlerTest) {
 
 TEST(SignalsDeathTest, BusDeathTest) {
   SignalAction actions;
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       []() -> void {
         // Bus error is tricky. There's one way that can work on POSIX systems
         // described below but it depends on mmaping a file. Just make it easy and
@@ -72,7 +74,7 @@ TEST(SignalsDeathTest, BusDeathTest) {
 
 TEST(SignalsDeathTest, BadMathDeathTest) {
   SignalAction actions;
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       []() -> void {
         // It turns out to be really hard to not have the optimizer get rid of a
         // division by zero. Just raise the signal for this test.
@@ -85,7 +87,7 @@ TEST(SignalsDeathTest, BadMathDeathTest) {
 // Unfortunately we don't have a reliable way to do this on other platforms
 TEST(SignalsDeathTest, IllegalInstructionDeathTest) {
   SignalAction actions;
-  EXPECT_DEATH_LOG_TO_STDERR(
+  EXPECT_DEATH(
       []() -> void {
         // Intel defines the "ud2" opcode to be an invalid instruction:
         __asm__("ud2");
@@ -96,7 +98,7 @@ TEST(SignalsDeathTest, IllegalInstructionDeathTest) {
 
 TEST(SignalsDeathTest, AbortDeathTest) {
   SignalAction actions;
-  EXPECT_DEATH_LOG_TO_STDERR([]() -> void { abort(); }(), "backtrace.*Abort(ed)?");
+  EXPECT_DEATH([]() -> void { abort(); }(), "backtrace.*Abort(ed)?");
 }
 
 TEST(SignalsDeathTest, RestoredPreviousHandlerDeathTest) {
@@ -108,7 +110,7 @@ TEST(SignalsDeathTest, RestoredPreviousHandlerDeathTest) {
     // goes out of scope, NOT the default.
   }
   // Outer SignalAction should be active again:
-  EXPECT_DEATH_LOG_TO_STDERR([]() -> void { abort(); }(), "backtrace.*Abort(ed)?");
+  EXPECT_DEATH([]() -> void { abort(); }(), "backtrace.*Abort(ed)?");
 }
 
 #endif

test/common/singleton/manager_impl_test.cc

@@ -18,8 +18,7 @@ static void deathTestWorker() {
 }
 
 TEST(SingletonManagerImplDeathTest, NotRegistered) {
-  EXPECT_DEATH_LOG_TO_STDERR(deathTestWorker(),
-                             "invalid singleton name 'foo'. Make sure it is registered.");
+  EXPECT_DEATH(deathTestWorker(), "invalid singleton name 'foo'. Make sure it is registered.");
 }
 
 SINGLETON_MANAGER_REGISTRATION(test);