From 733052a74d1e643f756a82ba3f80ef892f35dc63 Mon Sep 17 00:00:00 2001 From: alyssawilk Date: Wed, 3 Jul 2019 19:16:13 -0400 Subject: [PATCH] http: dumping session state on the decode path (#7390) Signed-off-by: Alyssa Wilk --- bazel/BUILD | 5 ++ bazel/README.md | 1 + bazel/envoy_internal.bzl | 3 + docs/root/intro/version_history.rst | 1 + include/envoy/common/BUILD | 5 ++ include/envoy/common/scope_tracker.h | 29 +++++++++ include/envoy/event/BUILD | 1 + include/envoy/event/dispatcher.h | 12 ++++ include/envoy/http/header_map.h | 18 +++--- source/common/common/BUILD | 16 +++++ source/common/common/dump_state_utils.h | 54 ++++++++++++++++ source/common/common/scope_tracker.h | 27 ++++++++ source/common/event/BUILD | 9 ++- source/common/event/dispatcher_impl.cc | 24 +++++-- source/common/event/dispatcher_impl.h | 24 ++++++- source/common/http/BUILD | 4 ++ source/common/http/conn_manager_impl.cc | 12 ++++ source/common/http/conn_manager_impl.h | 26 +++++++- source/common/http/header_map_impl.cc | 15 +++++ source/common/http/header_map_impl.h | 1 + source/common/signal/BUILD | 28 +++++++++ source/common/signal/fatal_error_handler.h | 18 ++++++ .../{exe => common/signal}/signal_action.cc | 51 ++++++++++++++- source/{exe => common/signal}/signal_action.h | 22 ++++++- source/common/stream_info/BUILD | 1 + source/common/stream_info/stream_info_impl.h | 8 +++ source/exe/BUILD | 14 +---- source/exe/main_common.h | 2 +- test/BUILD | 2 +- test/common/http/conn_manager_impl_test.cc | 63 +++++++++++++++++++ test/common/signal/BUILD | 19 ++++++ test/{exe => common/signal}/signals_test.cc | 22 ++++++- .../stream_info/stream_info_impl_test.cc | 14 +++++ test/exe/BUILD | 10 --- test/exe/main_common_test.cc | 2 +- test/main.cc | 2 +- test/mocks/event/mocks.h | 1 + 37 files changed, 518 insertions(+), 48 deletions(-) create mode 100644 include/envoy/common/scope_tracker.h create mode 100644 source/common/common/dump_state_utils.h create mode 100644 source/common/common/scope_tracker.h create mode 100644 source/common/signal/BUILD create mode 100644 source/common/signal/fatal_error_handler.h rename source/{exe => common/signal}/signal_action.cc (60%) rename source/{exe => common/signal}/signal_action.h (87%) create mode 100644 test/common/signal/BUILD rename test/{exe => common/signal}/signals_test.cc (84%) diff --git a/bazel/BUILD b/bazel/BUILD index c2fa24b88e93..c288f351054f 100755 --- a/bazel/BUILD +++ b/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"}, diff --git a/bazel/README.md b/bazel/README.md index 357a1b802f2f..25743ffdc097 100644 --- a/bazel/README.md +++ b/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 diff --git a/bazel/envoy_internal.bzl b/bazel/envoy_internal.bzl index f12d52b2570e..41b86a4d1b0a 100644 --- a/bazel/envoy_internal.bzl +++ b/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": [], diff --git a/docs/root/intro/version_history.rst b/docs/root/intro/version_history.rst index 6a8b03c954e9..29b24fcd4db2 100644 --- a/docs/root/intro/version_history.rst +++ b/docs/root/intro/version_history.rst @@ -38,6 +38,7 @@ Version history * http: added support for :ref:`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 ` 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` to distinguish locally and externally generated errors. See :ref:`arch_overview_outlier_detection` for full details. * listener: added :ref:`source IP ` diff --git a/include/envoy/common/BUILD b/include/envoy/common/BUILD index 1929682fb13c..4e04008c25d0 100644 --- a/include/envoy/common/BUILD +++ b/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"], +) diff --git a/include/envoy/common/scope_tracker.h b/include/envoy/common/scope_tracker.h new file mode 100644 index 000000000000..eb72edf3b7af --- /dev/null +++ b/include/envoy/common/scope_tracker.h @@ -0,0 +1,29 @@ +#pragma once + +#include + +#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 diff --git a/include/envoy/event/BUILD b/include/envoy/event/BUILD index 962e290e3808..05ea911bf8cc 100644 --- a/include/envoy/event/BUILD +++ b/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", diff --git a/include/envoy/event/dispatcher.h b/include/envoy/event/dispatcher.h index 50a6ddbadb86..4dbe2ab06e16 100644 --- a/include/envoy/event/dispatcher.h +++ b/include/envoy/event/dispatcher.h @@ -6,6 +6,7 @@ #include #include +#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; diff --git a/include/envoy/http/header_map.h b/include/envoy/http/header_map.h index 8af3b10e0b8d..050b3d0b2342 100644 --- a/include/envoy/http/header_map.h +++ b/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(context) << "'" << header.key().getStringView() << "', '" - << header.value().getStringView() << "'\n"; - return HeaderMap::Iterate::Continue; - }, - &os); + headers.dumpState(os); return os; } }; diff --git a/source/common/common/BUILD b/source/common/common/BUILD index bacfa4d4b06a..6ace52dbb343 100644 --- a/source/common/common/BUILD +++ b/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"], diff --git a/source/common/common/dump_state_utils.h b/source/common/common/dump_state_utils.h new file mode 100644 index 000000000000..c17c7b6c2ec6 --- /dev/null +++ b/source/common/common/dump_state_utils.h @@ -0,0 +1,54 @@ +#pragma once + +#include + +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 diff --git a/source/common/common/scope_tracker.h b/source/common/common/scope_tracker.h new file mode 100644 index 000000000000..bed58c3fa8c0 --- /dev/null +++ b/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 diff --git a/source/common/event/BUILD b/source/common/event/BUILD index 478fc28eb4c8..78461dcd3181 100644 --- a/source/common/event/BUILD +++ b/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( diff --git a/source/common/event/dispatcher_impl.cc b/source/common/event/dispatcher_impl.cc index 996ce9960471..7b718b8daf57 100644 --- a/source/common/event/dispatcher_impl.cc +++ b/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); } diff --git a/source/common/event/dispatcher_impl.h b/source/common/event/dispatcher_impl.h index ba95ee5684ea..51f71e8ad807 100644 --- a/source/common/event/dispatcher_impl.h +++ b/source/common/event/dispatcher_impl.h @@ -7,6 +7,7 @@ #include #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,6 +18,7 @@ #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 { @@ -24,7 +26,9 @@ namespace Event { /** * libevent implementation of Event::Dispatcher. */ -class DispatcherImpl : Logger::Loggable, public Dispatcher { +class DispatcherImpl : Logger::Loggable, + 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, public Dispatcher { void post(std::function 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, public Dispatcher { std::vector* current_to_delete_; Thread::MutexBasicLockable post_lock_; std::list> post_callbacks_ GUARDED_BY(post_lock_); + const ScopeTrackedObject* current_object_{}; bool deferred_deleting_{}; }; diff --git a/source/common/http/BUILD b/source/common/http/BUILD index 63ee261385d7..ce3737bef977 100644 --- a/source/common/http/BUILD +++ b/source/common/http/BUILD @@ -148,6 +148,7 @@ envoy_cc_library( ":utility_lib", "//include/envoy/access_log:access_log_interface", "//include/envoy/buffer:buffer_interface", + "//include/envoy/common:scope_tracker_interface", "//include/envoy/common:time_interface", "//include/envoy/event:deferred_deletable", "//include/envoy/event:dispatcher_interface", @@ -171,9 +172,11 @@ envoy_cc_library( "//source/common/access_log:access_log_formatter_lib", "//source/common/buffer:buffer_lib", "//source/common/common:assert_lib", + "//source/common/common:dump_state_utils", "//source/common/common:empty_string", "//source/common/common:enum_to_int", "//source/common/common:linked_object", + "//source/common/common:scope_tracker", "//source/common/common:utility_lib", "//source/common/http/http1:codec_lib", "//source/common/http/http2:codec_lib", @@ -214,6 +217,7 @@ envoy_cc_library( ":headers_lib", "//include/envoy/http:header_map_interface", "//source/common/common:assert_lib", + "//source/common/common:dump_state_utils", "//source/common/common:empty_string", "//source/common/common:non_copyable", "//source/common/common:utility_lib", diff --git a/source/common/http/conn_manager_impl.cc b/source/common/http/conn_manager_impl.cc index 0c5a221b7bf9..8e905ac5aba0 100644 --- a/source/common/http/conn_manager_impl.cc +++ b/source/common/http/conn_manager_impl.cc @@ -21,6 +21,7 @@ #include "common/common/empty_string.h" #include "common/common/enum_to_int.h" #include "common/common/fmt.h" +#include "common/common/scope_tracker.h" #include "common/common/utility.h" #include "common/http/codes.h" #include "common/http/conn_manager_utility.h" @@ -416,6 +417,9 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect connection_manager_.stats_.named_.downstream_rq_time_, connection_manager_.timeSource())), stream_info_(connection_manager_.codec_->protocol(), connection_manager_.timeSource()), upstream_options_(std::make_shared()) { + ScopeTrackerScopeState scope(this, + connection_manager_.read_callbacks_->connection().dispatcher()); + connection_manager_.stats_.named_.downstream_rq_total_.inc(); connection_manager_.stats_.named_.downstream_rq_active_.inc(); if (connection_manager_.codec_->protocol() == Protocol::Http2) { @@ -585,6 +589,8 @@ const Network::Connection* ConnectionManagerImpl::ActiveStream::connection() { // TODO(alyssawilk) all the calls here should be audited for order priority, // e.g. many early returns do not currently handle connection: close properly. void ConnectionManagerImpl::ActiveStream::decodeHeaders(HeaderMapPtr&& headers, bool end_stream) { + ScopeTrackerScopeState scope(this, + connection_manager_.read_callbacks_->connection().dispatcher()); request_headers_ = std::move(headers); if (Http::Headers::get().MethodValues.Head == request_headers_->Method()->value().getStringView()) { @@ -881,6 +887,8 @@ void ConnectionManagerImpl::ActiveStream::decodeHeaders(ActiveStreamDecoderFilte } void ConnectionManagerImpl::ActiveStream::decodeData(Buffer::Instance& data, bool end_stream) { + ScopeTrackerScopeState scope(this, + connection_manager_.read_callbacks_->connection().dispatcher()); maybeEndDecode(end_stream); stream_info_.addBytesReceived(data.length()); @@ -890,6 +898,8 @@ void ConnectionManagerImpl::ActiveStream::decodeData(Buffer::Instance& data, boo void ConnectionManagerImpl::ActiveStream::decodeData( ActiveStreamDecoderFilter* filter, Buffer::Instance& data, bool end_stream, FilterIterationStartState filter_iteration_start_state) { + ScopeTrackerScopeState scope(this, + connection_manager_.read_callbacks_->connection().dispatcher()); resetIdleTimer(); // If we previously decided to decode only the headers, do nothing here. @@ -1029,6 +1039,8 @@ void ConnectionManagerImpl::ActiveStream::addDecodedData(ActiveStreamDecoderFilt } void ConnectionManagerImpl::ActiveStream::decodeTrailers(HeaderMapPtr&& trailers) { + ScopeTrackerScopeState scope(this, + connection_manager_.read_callbacks_->connection().dispatcher()); resetIdleTimer(); maybeEndDecode(true); request_trailers_ = std::move(trailers); diff --git a/source/common/http/conn_manager_impl.h b/source/common/http/conn_manager_impl.h index 1e5b1901421e..a7ef3ef9eae8 100644 --- a/source/common/http/conn_manager_impl.h +++ b/source/common/http/conn_manager_impl.h @@ -9,6 +9,7 @@ #include #include "envoy/access_log/access_log.h" +#include "envoy/common/scope_tracker.h" #include "envoy/event/deferred_deletable.h" #include "envoy/http/codec.h" #include "envoy/http/codes.h" @@ -27,6 +28,7 @@ #include "envoy/upstream/upstream.h" #include "common/buffer/watermark_buffer.h" +#include "common/common/dump_state_utils.h" #include "common/common/linked_object.h" #include "common/grpc/common.h" #include "common/http/conn_manager_config.h" @@ -334,9 +336,10 @@ class ConnectionManagerImpl : Logger::Loggable, public StreamCallbacks, public StreamDecoder, public FilterChainFactoryCallbacks, - public Tracing::Config { + public Tracing::Config, + public ScopeTrackedObject { ActiveStream(ConnectionManagerImpl& connection_manager); - ~ActiveStream(); + ~ActiveStream() override; // Indicates which filter to start the iteration with. enum class FilterIterationStartState { AlwaysStartFromNext, CanStartFromCurrent }; @@ -417,6 +420,20 @@ class ConnectionManagerImpl : Logger::Loggable, const std::vector& requestHeadersForTags() const override; bool verbose() const override; + // ScopeTrackedObject + void dumpState(std::ostream& os, int indent_level = 0) const override { + const char* spaces = spacesForLevel(indent_level); + os << spaces << "ActiveStream " << this << DUMP_MEMBER(stream_id_) + << DUMP_MEMBER(has_continue_headers_) << DUMP_MEMBER(is_head_request_) + << DUMP_MEMBER(decoding_headers_only_) << DUMP_MEMBER(encoding_headers_only_) << "\n"; + + DUMP_DETAILS(request_headers_); + DUMP_DETAILS(request_trailers_); + DUMP_DETAILS(response_headers_); + DUMP_DETAILS(response_trailers_); + DUMP_DETAILS(&stream_info_); + } + void traceRequest(); void refreshCachedRoute(); @@ -494,6 +511,11 @@ class ConnectionManagerImpl : Logger::Loggable, bool hasCachedRoute() { return cached_route_.has_value() && cached_route_.value(); } + friend std::ostream& operator<<(std::ostream& os, const ActiveStream& s) { + s.dumpState(os); + return os; + } + ConnectionManagerImpl& connection_manager_; Router::ConfigConstSharedPtr snapped_route_config_; Router::ScopedConfigConstSharedPtr snapped_scoped_route_config_; diff --git a/source/common/http/header_map_impl.cc b/source/common/http/header_map_impl.cc index 2ceafa694186..ff018b77f9c6 100644 --- a/source/common/http/header_map_impl.cc +++ b/source/common/http/header_map_impl.cc @@ -6,6 +6,7 @@ #include #include "common/common/assert.h" +#include "common/common/dump_state_utils.h" #include "common/common/empty_string.h" #include "common/common/utility.h" #include "common/singleton/const_singleton.h" @@ -554,6 +555,20 @@ void HeaderMapImpl::removePrefix(const LowerCaseString& prefix) { }); } +void HeaderMapImpl::dumpState(std::ostream& os, int indent_level) const { + using IterateData = std::pair; + const char* spaces = spacesForLevel(indent_level); + IterateData iterate_data = std::make_pair(&os, spaces); + iterate( + [](const HeaderEntry& header, void* context) -> HeaderMap::Iterate { + auto* data = static_cast(context); + *data->first << data->second << "'" << header.key().getStringView() << "', '" + << header.value().getStringView() << "'\n"; + return HeaderMap::Iterate::Continue; + }, + &iterate_data); +} + HeaderMapImpl::HeaderEntryImpl& HeaderMapImpl::maybeCreateInline(HeaderEntryImpl** entry, const LowerCaseString& key) { if (*entry) { diff --git a/source/common/http/header_map_impl.h b/source/common/http/header_map_impl.h index 51b319499722..f7d3a66937f8 100644 --- a/source/common/http/header_map_impl.h +++ b/source/common/http/header_map_impl.h @@ -81,6 +81,7 @@ class HeaderMapImpl : public HeaderMap, NonCopyable { void removePrefix(const LowerCaseString& key) override; size_t size() const override { return headers_.size(); } bool empty() const override { return headers_.empty(); } + void dumpState(std::ostream& os, int indent_level = 0) const override; protected: // For tests only, unoptimized, they aren't intended for regular HeaderMapImpl users. diff --git a/source/common/signal/BUILD b/source/common/signal/BUILD new file mode 100644 index 000000000000..17dec6c9be55 --- /dev/null +++ b/source/common/signal/BUILD @@ -0,0 +1,28 @@ +licenses(["notice"]) # Apache 2 + +load( + "//bazel:envoy_build_system.bzl", + "envoy_cc_library", + "envoy_package", +) + +envoy_package() + +envoy_cc_library( + name = "fatal_error_handler_lib", + hdrs = ["fatal_error_handler.h"], +) + +envoy_cc_library( + name = "sigaction_lib", + srcs = ["signal_action.cc"], + hdrs = ["signal_action.h"], + tags = ["backtrace"], + deps = [ + ":fatal_error_handler_lib", + "//source/common/common:assert_lib", + "//source/common/common:non_copyable", + "//source/common/singleton:threadsafe_singleton", + "//source/server:backtrace_lib", + ], +) diff --git a/source/common/signal/fatal_error_handler.h b/source/common/signal/fatal_error_handler.h new file mode 100644 index 000000000000..95c185911d3e --- /dev/null +++ b/source/common/signal/fatal_error_handler.h @@ -0,0 +1,18 @@ +#pragma once + +#include "envoy/common/pure.h" + +namespace Envoy { + +// A simple class which allows registering functions to be called when Envoy +// receives one of the fatal signals, documented below. +// +// This is split out of signal_action.h because it is exempted from various +// builds. +class FatalErrorHandlerInterface { +public: + virtual ~FatalErrorHandlerInterface() = default; + virtual void onFatalError() const PURE; +}; + +} // namespace Envoy diff --git a/source/exe/signal_action.cc b/source/common/signal/signal_action.cc similarity index 60% rename from source/exe/signal_action.cc rename to source/common/signal/signal_action.cc index 00cfaf5d2c40..edc9dca40be9 100644 --- a/source/exe/signal_action.cc +++ b/source/common/signal/signal_action.cc @@ -1,4 +1,4 @@ -#include "exe/signal_action.h" +#include "common/signal/signal_action.h" #include @@ -7,6 +7,47 @@ #include "common/common/assert.h" namespace Envoy { + +ABSL_CONST_INIT static absl::Mutex failure_mutex(absl::kConstInit); +// Since we can't grab the failure mutex on fatal error (snagging locks under +// fatal crash causing potential deadlocks) access the handler list as an atomic +// operation, to minimize the chance that one thread is operating on the list +// while the crash handler is attempting to access it. +// This basically makes edits to the list thread-safe - if one thread is +// modifying the list rather than crashing in the crash handler due to accessing +// the list in a non-thread-safe manner, it simply won't log crash traces. +using FailureFunctionList = std::list; +ABSL_CONST_INIT std::atomic fatal_error_handlers{nullptr}; + +void SignalAction::registerFatalErrorHandler(const FatalErrorHandlerInterface& handler) { +#ifdef ENVOY_OBJECT_TRACE_ON_DUMP + absl::MutexLock l(&failure_mutex); + FailureFunctionList* list = fatal_error_handlers.exchange(nullptr, std::memory_order_relaxed); + if (list == nullptr) { + list = new FailureFunctionList; + } + list->push_back(&handler); + fatal_error_handlers.store(list, std::memory_order_release); +#else + UNREFERENCED_PARAMETER(handler); +#endif +} + +void SignalAction::removeFatalErrorHandler(const FatalErrorHandlerInterface& handler) { +#ifdef ENVOY_OBJECT_TRACE_ON_DUMP + absl::MutexLock l(&failure_mutex); + FailureFunctionList* list = fatal_error_handlers.exchange(nullptr, std::memory_order_relaxed); + list->remove(&handler); + if (list->empty()) { + delete list; + } else { + fatal_error_handlers.store(list, std::memory_order_release); + } +#else + UNREFERENCED_PARAMETER(handler); +#endif +} + constexpr int SignalAction::FATAL_SIGS[]; void SignalAction::sigHandler(int sig, siginfo_t* info, void* context) { @@ -20,6 +61,14 @@ void SignalAction::sigHandler(int sig, siginfo_t* info, void* context) { } tracer.logTrace(); + FailureFunctionList* list = fatal_error_handlers.exchange(nullptr, std::memory_order_relaxed); + if (list) { + // Finally after logging the stack trace, call any registered crash handlers. + for (const auto* handler : *list) { + handler->onFatalError(); + } + } + signal(sig, SIG_DFL); raise(sig); } diff --git a/source/exe/signal_action.h b/source/common/signal/signal_action.h similarity index 87% rename from source/exe/signal_action.h rename to source/common/signal/signal_action.h index 7af81167c5d0..12fcb1805a7b 100644 --- a/source/exe/signal_action.h +++ b/source/common/signal/signal_action.h @@ -4,12 +4,15 @@ #include #include +#include #include "common/common/non_copyable.h" +#include "common/signal/fatal_error_handler.h" #include "server/backtrace.h" namespace Envoy { + /** * This class installs signal handlers for fatal signal types. * @@ -50,8 +53,7 @@ class SignalAction : NonCopyable { public: SignalAction() : guard_size_(sysconf(_SC_PAGE_SIZE)), - altstack_size_(std::max(guard_size_ * 4, static_cast(MINSIGSTKSZ))), - altstack_(nullptr) { + altstack_size_(std::max(guard_size_ * 4, static_cast(MINSIGSTKSZ))), altstack_() { mapAndProtectStackMemory(); installSigHandlers(); } @@ -71,6 +73,18 @@ class SignalAction : NonCopyable { */ static void sigHandler(int sig, siginfo_t* info, void* context); + /** + * Add this handler to the list of functions which will be called if Envoy + * receives a fatal signal. + */ + static void registerFatalErrorHandler(const FatalErrorHandlerInterface& handler); + + /** + * Removes this handler from the list of functions which will be called if Envoy + * receives a fatal signal. + */ + static void removeFatalErrorHandler(const FatalErrorHandlerInterface& handler); + private: /** * Allocate this many bytes on each side of the area used for alt stack. @@ -125,8 +139,10 @@ class SignalAction : NonCopyable { * Unmap alternative stack memory. */ void unmapStackMemory(); - char* altstack_; + char* altstack_{}; std::array previous_handlers_; stack_t previous_altstack_; + std::list fatal_error_handlers_; }; + } // namespace Envoy diff --git a/source/common/stream_info/BUILD b/source/common/stream_info/BUILD index 639805f711f6..b80bdc6d4c06 100644 --- a/source/common/stream_info/BUILD +++ b/source/common/stream_info/BUILD @@ -15,6 +15,7 @@ envoy_cc_library( ":filter_state_lib", "//include/envoy/stream_info:stream_info_interface", "//source/common/common:assert_lib", + "//source/common/common:dump_state_utils", ], ) diff --git a/source/common/stream_info/stream_info_impl.h b/source/common/stream_info/stream_info_impl.h index d435a060e278..b434991af40b 100644 --- a/source/common/stream_info/stream_info_impl.h +++ b/source/common/stream_info/stream_info_impl.h @@ -7,6 +7,7 @@ #include "envoy/stream_info/stream_info.h" #include "common/common/assert.h" +#include "common/common/dump_state_utils.h" #include "common/stream_info/filter_state_impl.h" namespace Envoy { @@ -208,6 +209,13 @@ struct StreamInfoImpl : public StreamInfo { return upstream_transport_failure_reason_; } + void dumpState(std::ostream& os, int indent_level = 0) const { + const char* spaces = spacesForLevel(indent_level); + os << spaces << "StreamInfoImpl " << this << DUMP_OPTIONAL_MEMBER(protocol_) + << DUMP_OPTIONAL_MEMBER(response_code_) << DUMP_OPTIONAL_MEMBER(response_code_details_) + << DUMP_MEMBER(health_check_request_) << DUMP_MEMBER(route_name_) << "\n"; + } + TimeSource& time_source_; const SystemTime start_time_; const MonotonicTime start_time_monotonic_; diff --git a/source/exe/BUILD b/source/exe/BUILD index 2a1873e019ca..4117a4bb83ca 100644 --- a/source/exe/BUILD +++ b/source/exe/BUILD @@ -77,7 +77,7 @@ envoy_cc_library( ] + select({ "//bazel:disable_signal_trace": [], "//conditions:default": [ - ":sigaction_lib", + "//source/common/signal:sigaction_lib", ":terminate_handler_lib", ], }) + envoy_cc_platform_dep("platform_impl_lib"), @@ -117,18 +117,6 @@ envoy_cc_win32_library( ], ) -envoy_cc_library( - name = "sigaction_lib", - srcs = ["signal_action.cc"], - hdrs = ["signal_action.h"], - tags = ["backtrace"], - deps = [ - "//source/common/common:assert_lib", - "//source/common/common:non_copyable", - "//source/server:backtrace_lib", - ], -) - envoy_cc_library( name = "terminate_handler_lib", srcs = ["terminate_handler.cc"], diff --git a/source/exe/main_common.h b/source/exe/main_common.h index 3a49d8979099..a8944fd69b34 100644 --- a/source/exe/main_common.h +++ b/source/exe/main_common.h @@ -17,7 +17,7 @@ #include "server/server.h" #ifdef ENVOY_HANDLE_SIGNALS -#include "exe/signal_action.h" +#include "common/signal/signal_action.h" #include "exe/terminate_handler.h" #endif diff --git a/test/BUILD b/test/BUILD index fa80bf514d36..4c2e42990737 100644 --- a/test/BUILD +++ b/test/BUILD @@ -38,6 +38,6 @@ envoy_cc_test_library( "//test/test_common:printers_lib", ] + select({ "//bazel:disable_signal_trace": [], - "//conditions:default": ["//source/exe:sigaction_lib"], + "//conditions:default": ["//source/common/signal:sigaction_lib"], }), ) diff --git a/test/common/http/conn_manager_impl_test.cc b/test/common/http/conn_manager_impl_test.cc index 4a407492b78f..ce4e8af46284 100644 --- a/test/common/http/conn_manager_impl_test.cc +++ b/test/common/http/conn_manager_impl_test.cc @@ -51,6 +51,7 @@ using testing::AnyNumber; using testing::AtLeast; using testing::DoAll; using testing::Eq; +using testing::HasSubstr; using testing::InSequence; using testing::Invoke; using testing::InvokeWithoutArgs; @@ -4294,5 +4295,67 @@ TEST_F(HttpConnectionManagerImplTest, DisableKeepAliveWhenDraining) { Buffer::OwnedImpl fake_input; conn_manager_->onData(fake_input, false); } + +TEST_F(HttpConnectionManagerImplTest, TestSessionTrace) { + setup(false, ""); + + // Set up the codec. + EXPECT_CALL(*codec_, dispatch(_)).WillRepeatedly(Invoke([&](Buffer::Instance& data) -> void { + data.drain(4); + })); + Buffer::OwnedImpl fake_input("1234"); + conn_manager_->onData(fake_input, false); + + setupFilterChain(1, 1); + + // Create a new stream + StreamDecoder* decoder = &conn_manager_->newStream(response_encoder_); + + // Send headers to that stream, and verify we both set and clear the tracked object. + { + HeaderMapPtr headers{ + new TestHeaderMapImpl{{":authority", "host"}, {":path", "/"}, {":method", "POST"}}}; + EXPECT_CALL(filter_callbacks_.connection_.dispatcher_, setTrackedObject(_)) + .Times(2) + .WillOnce(Invoke([](const ScopeTrackedObject* object) -> const ScopeTrackedObject* { + ASSERT(object != nullptr); // On the first call, this should be the active stream. + std::stringstream out; + object->dumpState(out); + std::string state = out.str(); + EXPECT_THAT(state, testing::HasSubstr("request_headers_: null")); + EXPECT_THAT(state, testing::HasSubstr("protocol_: 1")); + return nullptr; + })) + .WillRepeatedly(Return(nullptr)); + EXPECT_CALL(*decoder_filters_[0], decodeHeaders(_, false)) + .WillOnce(Invoke([](HeaderMap&, bool) -> FilterHeadersStatus { + return FilterHeadersStatus::StopIteration; + })); + decoder->decodeHeaders(std::move(headers), false); + } + + // Send trailers to that stream, and verify by this point headers are in logged state. + { + HeaderMapPtr trailers{new TestHeaderMapImpl{{"foo", "bar"}}}; + EXPECT_CALL(filter_callbacks_.connection_.dispatcher_, setTrackedObject(_)) + .Times(2) + .WillOnce(Invoke([](const ScopeTrackedObject* object) -> const ScopeTrackedObject* { + ASSERT(object != nullptr); // On the first call, this should be the active stream. + std::stringstream out; + object->dumpState(out); + std::string state = out.str(); + EXPECT_THAT(state, testing::HasSubstr("request_headers_: \n")); + EXPECT_THAT(state, testing::HasSubstr("':authority', 'host'\n")); + EXPECT_THAT(state, testing::HasSubstr("protocol_: 1")); + return nullptr; + })) + .WillRepeatedly(Return(nullptr)); + EXPECT_CALL(*decoder_filters_[0], decodeComplete()); + EXPECT_CALL(*decoder_filters_[0], decodeTrailers(_)) + .WillOnce(Return(FilterTrailersStatus::StopIteration)); + decoder->decodeTrailers(std::move(trailers)); + } +} + } // namespace Http } // namespace Envoy diff --git a/test/common/signal/BUILD b/test/common/signal/BUILD new file mode 100644 index 000000000000..c29cfd2a56b3 --- /dev/null +++ b/test/common/signal/BUILD @@ -0,0 +1,19 @@ +licenses(["notice"]) # Apache 2 + +load( + "//bazel:envoy_build_system.bzl", + "envoy_cc_test", + "envoy_package", +) + +envoy_package() + +envoy_cc_test( + name = "signals_test", + srcs = ["signals_test.cc"], + tags = ["backtrace"], + deps = [ + "//source/common/signal:sigaction_lib", + "//test/test_common:utility_lib", + ], +) diff --git a/test/exe/signals_test.cc b/test/common/signal/signals_test.cc similarity index 84% rename from test/exe/signals_test.cc rename to test/common/signal/signals_test.cc index eb07fe61370a..72b28c7bbf8b 100644 --- a/test/exe/signals_test.cc +++ b/test/common/signal/signals_test.cc @@ -1,7 +1,7 @@ #include #include -#include "exe/signal_action.h" +#include "common/signal/signal_action.h" #include "test/test_common/utility.h" @@ -34,6 +34,25 @@ TEST(SignalsDeathTest, InvalidAddressDeathTest) { "backtrace.*Segmentation fault"); } +class TestFatalErrorHandler : public FatalErrorHandlerInterface { + virtual void onFatalError() const override { std::cerr << "HERE!"; } +}; + +TEST(SignalsDeathTest, RegisteredHandlerTest) { + TestFatalErrorHandler handler; + SignalAction::registerFatalErrorHandler(handler); + SignalAction actions; + // Make sure the fatal error log "HERE" registered above is logged on fatal error. + EXPECT_DEATH_LOG_TO_STDERR( + []() -> void { + // Oops! + volatile int* nasty_ptr = reinterpret_cast(0x0); + *(nasty_ptr) = 0; + }(), + "HERE"); + SignalAction::removeFatalErrorHandler(handler); +} + TEST(SignalsDeathTest, BusDeathTest) { SignalAction actions; EXPECT_DEATH_LOG_TO_STDERR( @@ -90,6 +109,7 @@ TEST(SignalsDeathTest, RestoredPreviousHandlerDeathTest) { // Outer SignalAction should be active again: EXPECT_DEATH_LOG_TO_STDERR([]() -> void { abort(); }(), "backtrace.*Abort(ed)?"); } + #endif TEST(SignalsDeathTest, IllegalStackAccessDeathTest) { diff --git a/test/common/stream_info/stream_info_impl_test.cc b/test/common/stream_info/stream_info_impl_test.cc index fec622ddc810..380f60ffcebb 100644 --- a/test/common/stream_info/stream_info_impl_test.cc +++ b/test/common/stream_info/stream_info_impl_test.cc @@ -201,6 +201,20 @@ TEST_F(StreamInfoImplTest, DynamicMetadataTest) { EXPECT_TRUE(json.find("\"another_key\":\"another_value\"") != std::string::npos); } +TEST_F(StreamInfoImplTest, DumpStateTest) { + StreamInfoImpl stream_info(Http::Protocol::Http2, test_time_.timeSystem()); + std::string prefix = ""; + + for (int i = 0; i < 7; ++i) { + std::stringstream out; + stream_info.dumpState(out, i); + std::string state = out.str(); + EXPECT_TRUE(absl::StartsWith(state, prefix)); + EXPECT_THAT(state, testing::HasSubstr("protocol_: 2")); + prefix = prefix + " "; + } +} + } // namespace } // namespace StreamInfo } // namespace Envoy diff --git a/test/exe/BUILD b/test/exe/BUILD index 641b1c9efc60..12235850ca35 100644 --- a/test/exe/BUILD +++ b/test/exe/BUILD @@ -52,16 +52,6 @@ envoy_cc_test( ], ) -envoy_cc_test( - name = "signals_test", - srcs = ["signals_test.cc"], - tags = ["backtrace"], - deps = [ - "//source/exe:sigaction_lib", - "//test/test_common:utility_lib", - ], -) - envoy_cc_test( name = "terminate_handler_test", srcs = ["terminate_handler_test.cc"], diff --git a/test/exe/main_common_test.cc b/test/exe/main_common_test.cc index 44c693a91f8e..baeeb243976a 100644 --- a/test/exe/main_common_test.cc +++ b/test/exe/main_common_test.cc @@ -16,7 +16,7 @@ #include "gtest/gtest.h" #ifdef ENVOY_HANDLE_SIGNALS -#include "exe/signal_action.h" +#include "common/signal/signal_action.h" #endif #include "absl/synchronization/notification.h" diff --git a/test/main.cc b/test/main.cc index 83a9d2b72c9f..b7295edd0b02 100644 --- a/test/main.cc +++ b/test/main.cc @@ -8,7 +8,7 @@ #include "absl/debugging/symbolize.h" #ifdef ENVOY_HANDLE_SIGNALS -#include "exe/signal_action.h" +#include "common/signal/signal_action.h" #endif // The main entry point (and the rest of this file) should have no logic in it, diff --git a/test/mocks/event/mocks.h b/test/mocks/event/mocks.h index 4237a3b57ca0..5cbd2f076f5f 100644 --- a/test/mocks/event/mocks.h +++ b/test/mocks/event/mocks.h @@ -113,6 +113,7 @@ class MockDispatcher : public Dispatcher { MOCK_METHOD2(listenForSignal_, SignalEvent*(int signal_num, SignalCb cb)); MOCK_METHOD1(post, void(std::function callback)); MOCK_METHOD1(run, void(RunType type)); + MOCK_METHOD1(setTrackedObject, const ScopeTrackedObject*(const ScopeTrackedObject* object)); Buffer::WatermarkFactory& getWatermarkFactory() override { return buffer_factory_; } GlobalTimeSystem time_system_;