http: dumping session state on the decode path (#7390)

Signed-off-by: Alyssa Wilk <[email protected]>

bazel/BUILD

@@ -100,6 +100,11 @@ config_setting(
     values = {"define": "signal_trace=disabled"},
 )
 
+config_setting(
+    name = "disable_object_dump_on_signal_trace",
+    values = {"define": "object_dump_on_signal_trace=disabled"},
+)
+
 config_setting(
     name = "disable_hot_restart",
     values = {"define": "hot_restart=disabled"},

bazel/README.md

@@ -350,6 +350,7 @@ The following optional features can be disabled on the Bazel build command-line:
 * Hot restart with `--define hot_restart=disabled`
 * Google C++ gRPC client with `--define google_grpc=disabled`
 * Backtracing on signals with `--define signal_trace=disabled`
+* Active stream state dump on signals with `--define signal_trace=disabled` or `--define disable_object_dump_on_signal_trace=disabled`
 * tcmalloc with `--define tcmalloc=disabled`
 
 ## Enabling optional features

bazel/envoy_internal.bzl

@@ -49,6 +49,9 @@ def envoy_copts(repository, test = False):
            }) + select({
                repository + "//bazel:disable_signal_trace": [],
                "//conditions:default": ["-DENVOY_HANDLE_SIGNALS"],
+           }) + select({
+               repository + "//bazel:disable_object_dump_on_signal_trace": [],
+               "//conditions:default": ["-DENVOY_OBJECT_TRACE_ON_DUMP"],
            }) + select({
                repository + "//bazel:enable_log_debug_assert_in_release": ["-DENVOY_LOG_DEBUG_ASSERT_IN_RELEASE"],
                "//conditions:default": [],

docs/root/intro/version_history.rst

@@ -38,6 +38,7 @@ Version history
 * http: added support for :ref:`preserve_external_request_id<envoy_api_field_config.filter.network.http_connection_manager.v2.HttpConnectionManager.preserve_external_request_id>` that represents whether the x-request-id should not be reset on edge entry inside mesh
 * http: changed `sendLocalReply` to send percent-encoded `GrpcMessage`.
 * http: added :ref:`dynamic forward proxy <arch_overview_http_dynamic_forward_proxy>` support.
+* http: tracking the active stream and dumping state in Envoy crash handlers. This can be disabled by building with `--define disable_object_dump_on_signal_trace=disabled`
 * jwt_authn: make filter's parsing of JWT more flexible, allowing syntax like ``jwt=eyJhbGciOiJS...ZFnFIw,extra=7,realm=123``
 * outlier_detector: added configuration :ref:`outlier_detection.split_external_local_origin_errors<envoy_api_field_cluster.OutlierDetection.split_external_local_origin_errors>` to distinguish locally and externally generated errors. See :ref:`arch_overview_outlier_detection` for full details.
 * listener: added :ref:`source IP <envoy_api_field_listener.FilterChainMatch.source_prefix_ranges>`

include/envoy/common/BUILD

@@ -51,3 +51,8 @@ envoy_cc_library(
     name = "backoff_strategy_interface",
     hdrs = ["backoff_strategy.h"],
 )
+
+envoy_cc_library(
+    name = "scope_tracker_interface",
+    hdrs = ["scope_tracker.h"],
+)

include/envoy/common/scope_tracker.h

@@ -0,0 +1,29 @@
+#pragma once
+
+#include <ostream>
+
+#include "envoy/common/pure.h"
+
+namespace Envoy {
+
+/*
+ * A class for tracking the scope of work.
+ * Currently this is only used for best-effort tracking the L7 stream doing
+ * work if a fatal error occurs.
+ */
+class ScopeTrackedObject {
+public:
+  virtual ~ScopeTrackedObject() = default;
+
+  /**
+   * Dump debug state of the object in question to the provided ostream
+   *
+   * This is called on Envoy fatal errors, so should do minimal memory allocation.
+   *
+   * @param os the ostream to output to.
+   * @param indent_level how far to indent, for pretty-printed classes and subclasses.
+   */
+  virtual void dumpState(std::ostream& os, int indent_level = 0) const PURE;
+};
+
+} // namespace Envoy

include/envoy/event/BUILD

@@ -20,6 +20,7 @@ envoy_cc_library(
         ":deferred_deletable",
         ":file_event_interface",
         ":signal_interface",
+        "//include/envoy/common:scope_tracker_interface",
         "//include/envoy/common:time_interface",
         "//include/envoy/event:timer_interface",
         "//include/envoy/filesystem:watcher_interface",

include/envoy/event/dispatcher.h

@@ -6,6 +6,7 @@
 #include <string>
 #include <vector>
 
+#include "envoy/common/scope_tracker.h"
 #include "envoy/common/time.h"
 #include "envoy/event/file_event.h"
 #include "envoy/event/signal.h"
@@ -199,6 +200,17 @@ class Dispatcher {
    * @return the watermark buffer factory for this dispatcher.
    */
   virtual Buffer::WatermarkFactory& getWatermarkFactory() PURE;
+
+  /**
+   * Sets a tracked object, which is currently operating in this Dispatcher.
+   * This should be cleared with another call to setTrackedObject() when the object is done doing
+   * work. Calling setTrackedObject(nullptr) results in no object being tracked.
+   *
+   * This is optimized for performance, to avoid allocation where we do scoped object tracking.
+   *
+   * @return The previously tracked object or nullptr if there was none.
+   */
+  virtual const ScopeTrackedObject* setTrackedObject(const ScopeTrackedObject* object) PURE;
 };
 
 using DispatcherPtr = std::unique_ptr<Dispatcher>;

include/envoy/http/header_map.h

@@ -527,19 +527,23 @@ class HeaderMap {
    */
   virtual bool empty() const PURE;
 
+  /**
+   * Dump the header map to the ostream specified
+   *
+   * @param os the stream to dump state to
+   * @param indent_level the depth, for pretty-printing.
+   *
+   * This function is called on Envoy fatal errors so should avoid memory allocation where possible.
+   */
+  virtual void dumpState(std::ostream& os, int indent_level = 0) const PURE;
+
   /**
    * Allow easy pretty-printing of the key/value pairs in HeaderMap
    * @param os supplies the ostream to print to.
    * @param headers the headers to print.
    */
   friend std::ostream& operator<<(std::ostream& os, const HeaderMap& headers) {
-    headers.iterate(
-        [](const HeaderEntry& header, void* context) -> HeaderMap::Iterate {
-          *static_cast<std::ostream*>(context) << "'" << header.key().getStringView() << "', '"
-                                               << header.value().getStringView() << "'\n";
-          return HeaderMap::Iterate::Continue;
-        },
-        &os);
+    headers.dumpState(os);
     return os;
   }
 };

source/common/common/BUILD

@@ -109,6 +109,12 @@ envoy_cc_library(
     deps = [":assert_lib"],
 )
 
+# Contains macros and helpers for dumpState utilities
+envoy_cc_library(
+    name = "dump_state_utils",
+    hdrs = ["dump_state_utils.h"],
+)
+
 # Contains minimal code for logging to stderr.
 envoy_cc_library(
     name = "minimal_logger_lib",
@@ -140,6 +146,7 @@ envoy_cc_library(
     srcs = ["logger_delegates.cc"],
     hdrs = ["logger_delegates.h"],
     deps = [
+        ":dump_state_utils",
         ":macros",
         ":minimal_logger_lib",
         "//include/envoy/access_log:access_log_interface",
@@ -177,6 +184,15 @@ envoy_cc_library(
     hdrs = ["phantom.h"],
 )
 
+envoy_cc_library(
+    name = "scope_tracker",
+    hdrs = ["scope_tracker.h"],
+    deps = [
+        "//include/envoy/common:scope_tracker_interface",
+        "//include/envoy/event:dispatcher_interface",
+    ],
+)
+
 envoy_cc_library(
     name = "stl_helpers",
     hdrs = ["stl_helpers.h"],

source/common/common/dump_state_utils.h

@@ -0,0 +1,54 @@
+#pragma once
+
+#include <sstream>
+
+namespace Envoy {
+
+// A collection of macros for pretty printing objects on fatal error.
+// These are fairly ugly in an attempt to maximize the conditions where fatal error logging occurs,
+// i.e. under the Envoy signal handler if encountering a crash due to OOM, where allocating more
+// memory would likely lead to the crash handler itself causing a subsequent OOM.
+
+#define DUMP_MEMBER(member) ", " #member ": " << (member)
+
+#define DUMP_OPTIONAL_MEMBER(member)                                                               \
+  ", " #member ": " << ((member).has_value() ? absl::StrCat((member).value()) : "null")
+
+// Macro assumes local member variables
+// os (ostream)
+// indent_level (int)
+#define DUMP_DETAILS(member)                                                                       \
+  do {                                                                                             \
+    os << spaces << #member ": ";                                                                  \
+    if ((member) != nullptr) {                                                                     \
+      os << "\n";                                                                                  \
+      (member)->dumpState(os, indent_level + 1);                                                   \
+    } else {                                                                                       \
+      os << spaces << "null\n";                                                                    \
+    }                                                                                              \
+  } while (false)
+
+// Return the const char* equivalent of string(level*2, ' '), without dealing
+// with string creation overhead. Cap arbitrarily at 6 as we're (hopefully)
+// not going to have nested objects deeper than that.
+inline const char* spacesForLevel(int level) {
+  switch (level) {
+  case 0:
+    return "";
+  case 1:
+    return "  ";
+  case 2:
+    return "    ";
+  case 3:
+    return "      ";
+  case 4:
+    return "        ";
+  case 5:
+    return "          ";
+  default:
+    return "            ";
+  }
+  return "";
+}
+
+} // namespace Envoy

source/common/common/scope_tracker.h

@@ -0,0 +1,27 @@
+#pragma once
+
+#include "envoy/common/scope_tracker.h"
+#include "envoy/event/dispatcher.h"
+
+namespace Envoy {
+
+// A small class for tracking the scope of the object which is currently having
+// work done in this thread.
+//
+// When created, it sets the tracked object in the dispatcher, and when destroyed it points the
+// dispatcher at the previously tracked object.
+class ScopeTrackerScopeState {
+public:
+  ScopeTrackerScopeState(const ScopeTrackedObject* object, Event::Dispatcher& dispatcher)
+      : dispatcher_(dispatcher) {
+    latched_object_ = dispatcher_.setTrackedObject(object);
+  }
+
+  ~ScopeTrackerScopeState() { dispatcher_.setTrackedObject(latched_object_); }
+
+private:
+  const ScopeTrackedObject* latched_object_;
+  Event::Dispatcher& dispatcher_;
+};
+
+} // namespace Envoy

source/common/event/BUILD

@@ -22,6 +22,7 @@ envoy_cc_library(
         ":dispatcher_includes",
         ":libevent_scheduler_lib",
         ":real_time_system_lib",
+        "//include/envoy/common:scope_tracker_interface",
         "//include/envoy/common:time_interface",
         "//include/envoy/event:signal_interface",
         "//include/envoy/network:listen_socket_interface",
@@ -74,7 +75,13 @@ envoy_cc_library(
         "//include/envoy/network:connection_handler_interface",
         "//source/common/common:minimal_logger_lib",
         "//source/common/common:thread_lib",
-    ],
+        "//source/common/signal:fatal_error_handler_lib",
+    ] + select({
+        "//bazel:disable_signal_trace": [],
+        "//conditions:default": [
+            "//source/common/signal:sigaction_lib",
+        ],
+    }),
 )
 
 envoy_cc_library(

source/common/event/dispatcher_impl.cc

@@ -25,6 +25,10 @@
 
 #include "event2/event.h"
 
+#ifdef ENVOY_HANDLE_SIGNALS
+#include "common/signal/signal_action.h"
+#endif
+
 namespace Envoy {
 namespace Event {
 
@@ -35,11 +39,19 @@ DispatcherImpl::DispatcherImpl(Buffer::WatermarkFactoryPtr&& factory, Api::Api&
                                Event::TimeSystem& time_system)
     : api_(api), buffer_factory_(std::move(factory)),
       scheduler_(time_system.createScheduler(base_scheduler_)),
-      deferred_delete_timer_(createTimer([this]() -> void { clearDeferredDeleteList(); })),
-      post_timer_(createTimer([this]() -> void { runPostCallbacks(); })),
-      current_to_delete_(&to_delete_1_) {}
+      deferred_delete_timer_(createTimerInternal([this]() -> void { clearDeferredDeleteList(); })),
+      post_timer_(createTimerInternal([this]() -> void { runPostCallbacks(); })),
+      current_to_delete_(&to_delete_1_) {
+#ifdef ENVOY_HANDLE_SIGNALS
+  SignalAction::registerFatalErrorHandler(*this);
+#endif
+}
 
-DispatcherImpl::~DispatcherImpl() {}
+DispatcherImpl::~DispatcherImpl() {
+#ifdef ENVOY_HANDLE_SIGNALS
+  SignalAction::removeFatalErrorHandler(*this);
+#endif
+}
 
 void DispatcherImpl::initializeStats(Stats::Scope& scope, const std::string& prefix) {
   // This needs to be run in the dispatcher's thread, so that we have a thread id to log.
@@ -133,7 +145,9 @@ Network::ListenerPtr DispatcherImpl::createUdpListener(Network::Socket& socket,
   return Network::ListenerPtr{new Network::UdpListenerImpl(*this, socket, cb, timeSource())};
 }
 
-TimerPtr DispatcherImpl::createTimer(TimerCb cb) {
+TimerPtr DispatcherImpl::createTimer(TimerCb cb) { return createTimerInternal(cb); }
+
+TimerPtr DispatcherImpl::createTimerInternal(TimerCb cb) {
   ASSERT(isThreadSafe());
   return scheduler_->createTimer(cb);
 }

source/common/event/dispatcher_impl.h

@@ -7,6 +7,7 @@
 #include <vector>
 
 #include "envoy/api/api.h"
+#include "envoy/common/scope_tracker.h"
 #include "envoy/common/time.h"
 #include "envoy/event/deferred_deletable.h"
 #include "envoy/event/dispatcher.h"
@@ -17,14 +18,17 @@
 #include "common/common/thread.h"
 #include "common/event/libevent.h"
 #include "common/event/libevent_scheduler.h"
+#include "common/signal/fatal_error_handler.h"
 
 namespace Envoy {
 namespace Event {
 
 /**
  * libevent implementation of Event::Dispatcher.
  */
-class DispatcherImpl : Logger::Loggable<Logger::Id::main>, public Dispatcher {
+class DispatcherImpl : Logger::Loggable<Logger::Id::main>,
+                       public Dispatcher,
+                       public FatalErrorHandlerInterface {
 public:
   DispatcherImpl(Api::Api& api, Event::TimeSystem& time_system);
   DispatcherImpl(Buffer::WatermarkFactoryPtr&& factory, Api::Api& api,
@@ -65,8 +69,25 @@ class DispatcherImpl : Logger::Loggable<Logger::Id::main>, public Dispatcher {
   void post(std::function<void()> callback) override;
   void run(RunType type) override;
   Buffer::WatermarkFactory& getWatermarkFactory() override { return *buffer_factory_; }
+  const ScopeTrackedObject* setTrackedObject(const ScopeTrackedObject* object) override {
+    const ScopeTrackedObject* return_object = current_object_;
+    current_object_ = object;
+    return return_object;
+  }
+
+  // FatalErrorInterface
+  void onFatalError() const override {
+    // Dump the state of the tracked object if it is in the current thread. This generally results
+    // in dumping the active state only for the thread which caused the fatal error.
+    if (isThreadSafe()) {
+      if (current_object_) {
+        current_object_->dumpState(std::cerr);
+      }
+    }
+  }
 
 private:
+  TimerPtr createTimerInternal(TimerCb cb);
   void runPostCallbacks();
 
   // Validate that an operation is thread safe, i.e. it's invoked on the same thread that the
@@ -90,6 +111,7 @@ class DispatcherImpl : Logger::Loggable<Logger::Id::main>, public Dispatcher {
   std::vector<DeferredDeletablePtr>* current_to_delete_;
   Thread::MutexBasicLockable post_lock_;
   std::list<std::function<void()>> post_callbacks_ GUARDED_BY(post_lock_);
+  const ScopeTrackedObject* current_object_{};
   bool deferred_deleting_{};
 };