Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

http: dumping session state on the decode path #7390

Merged
merged 14 commits into from
Jul 3, 2019
5 changes: 5 additions & 0 deletions include/envoy/common/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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"],
)
27 changes: 27 additions & 0 deletions include/envoy/common/scope_tracker.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
#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 any L7 stream doing
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/the any/any ?

* work if a crash occurs.
*/
class ScopeTrackedObject {
public:
virtual ~ScopeTrackedObject() {}

/**
* Dump debug state of the object in question to the provided ostream
*
* @param os the ostream to output to.
* @param indent_level how far to indent, for pretty-printed classes and subclasses.
*/
virtual void logState(std::ostream& os, int indent_level = 0) const PURE;
htuch marked this conversation as resolved.
Show resolved Hide resolved
};

} // namespace Envoy
1 change: 1 addition & 0 deletions include/envoy/event/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
10 changes: 10 additions & 0 deletions include/envoy/event/dispatcher.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -199,6 +200,15 @@ 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.
mattklein123 marked this conversation as resolved.
Show resolved Hide resolved
* This should be cleared with another call to setTrackedObject() when the object is done doing
* work.
htuch marked this conversation as resolved.
Show resolved Hide resolved
*
* @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>;
Expand Down
1 change: 1 addition & 0 deletions include/envoy/http/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -76,6 +76,7 @@ envoy_cc_library(
deps = [
"//source/common/common:assert_lib",
"//source/common/common:hash_lib",
"//source/common/common:log_state_utils",
],
)

Expand Down
23 changes: 16 additions & 7 deletions include/envoy/http/header_map.h
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@

#include "common/common/assert.h"
#include "common/common/hash.h"
#include "common/common/log_state_utils.h"
#include "common/common/macros.h"

#include "absl/strings/string_view.h"
Expand Down Expand Up @@ -525,19 +526,27 @@ class HeaderMap {
*/
virtual bool empty() const PURE;

void logState(std::ostream& os, int indent_level = 0) const {
typedef std::pair<std::ostream*, const char*> IterateData;
const char* spaces = spacesForLevel(indent_level);
IterateData iterate_data = std::make_pair(&os, spaces);
iterate(
[](const HeaderEntry& header, void* context) -> HeaderMap::Iterate {
IterateData* data = static_cast<IterateData*>(context);
*data->first << data->second << "'" << header.key().getStringView() << "', '"
<< header.value().getStringView() << "'\n";
return HeaderMap::Iterate::Continue;
},
&iterate_data);
}
htuch marked this conversation as resolved.
Show resolved Hide resolved

/**
* 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.logState(os);
return os;
}
};
Expand Down
15 changes: 15 additions & 0 deletions source/common/common/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -109,6 +109,12 @@ envoy_cc_library(
deps = [":assert_lib"],
)

# Contains macros and helpers for logState utilities
envoy_cc_library(
name = "log_state_utils",
hdrs = ["log_state_utils.h"],
)

# Contains minimal code for logging to stderr.
envoy_cc_library(
name = "minimal_logger_lib",
Expand Down Expand Up @@ -140,6 +146,7 @@ envoy_cc_library(
srcs = ["logger_delegates.cc"],
hdrs = ["logger_delegates.h"],
deps = [
":log_state_utils",
":macros",
":minimal_logger_lib",
"//include/envoy/access_log:access_log_interface",
Expand Down Expand Up @@ -177,6 +184,14 @@ envoy_cc_library(
hdrs = ["phantom.h"],
)

envoy_cc_library(
name = "scope_tracker",
hdrs = ["scope_tracker.h"],
deps = [
"//include/envoy/common:scope_tracker_interface",
],
)

envoy_cc_library(
name = "stl_helpers",
hdrs = ["stl_helpers.h"],
Expand Down
49 changes: 49 additions & 0 deletions source/common/common/log_state_utils.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
#pragma once

#include <sstream>

namespace Envoy {

#define LOG_MEMBER(member) ", " #member ": " << (member)

#define LOG_OPTIONAL_MEMBER(member) \
", " #member ": " << (member.has_value() ? absl::StrCat(member.value()) : "null")

// Macro assumes local member variables
// os (ostream)
// indent_level (int)
#define LOG_DETAILS(member) \
do { \
os << spaces << #member ": "; \
if (member != nullptr) { \
os << "\n"; \
(member)->logState(os, indent_level + 1); \
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not a huge fan of this style of printing and indenting TBH. I get that you want to make this efficient and have no allocations, but it's leaking through above into a duck typing of a pure interface (the header map), which seems like a pattern best avoided across if it's going to appear in more places.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, to your point I think there is value in having a structured data print type, and I can think of several use cases where it'd be valuable internally. From (possibly outdated?) priors I believe there is also value in a minimal allocation state drop, which is what I planned on implementing first. I think for out-process communication and machine-consumption we'll eventually want to tackle the latter, but I don't think we'd want to use that version in the fatal error handler and I'd like the "core dumps are hard" session state to be human readable where possible.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a fair point. I think it would be useful to document (i.e. provide the citations) on how allocations during fatal handling are a problem. The main one I can imagine is that we're in a soft OOM situation, and allocation would lead to a hard OOM, would be good to have some more intuition on this one.

} 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) {
htuch marked this conversation as resolved.
Show resolved Hide resolved
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
22 changes: 22 additions & 0 deletions source/common/common/scope_tracker.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,22 @@
#pragma once

#include "envoy/common/scope_tracker.h"
#include "envoy/event/dispatcher.h"

namespace Envoy {

class ScopeTrackerImpl {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: I might call this RAIIScopeTracker or something like that? Since this isn't really an implementation of anything?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this name is better future-proofed for when we use the scope object for customer memory/cpu accounting (the htuch@ feature) - WDYT?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't feel strongly about it, other than to say that Impl usually is an implementation of an interface which this is not, so I would probably try to find a more descriptive name which IMO is some type of context or something along those lines. e.g. ScopeTrackerScopeState or something. Anyway, not a big deal either way.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(I guess a small class comment on what it is for would be nice either way)

public:
ScopeTrackerImpl(const ScopeTrackedObject* object, Event::Dispatcher& dispatcher)
: dispatcher_(dispatcher) {
latched_object_ = dispatcher_.setTrackedObject(object);
}

~ScopeTrackerImpl() { dispatcher_.setTrackedObject(latched_object_); }

private:
const ScopeTrackedObject* latched_object_;
Event::Dispatcher& dispatcher_;
};

} // namespace Envoy
8 changes: 7 additions & 1 deletion source/common/event/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down Expand Up @@ -74,7 +75,12 @@ envoy_cc_library(
"//include/envoy/network:connection_handler_interface",
"//source/common/common:minimal_logger_lib",
"//source/common/common:thread_lib",
],
] + select({
"//bazel:disable_signal_trace": [],
"//conditions:default": [
"//source/exe:sigaction_lib",
],
}),
)

envoy_cc_library(
Expand Down
12 changes: 10 additions & 2 deletions source/common/event/dispatcher_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -37,9 +37,17 @@ DispatcherImpl::DispatcherImpl(Buffer::WatermarkFactoryPtr&& factory, Api::Api&
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_) {}
current_to_delete_(&to_delete_1_) {
#ifdef ENVOY_HANDLE_SIGNALS
SignalAction::registerCrashHandler(*this);
#endif
}

DispatcherImpl::~DispatcherImpl() {}
DispatcherImpl::~DispatcherImpl() {
#ifdef ENVOY_HANDLE_SIGNALS
SignalAction::removeCrashHandler(*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.
Expand Down
24 changes: 23 additions & 1 deletion source/common/event/dispatcher_impl.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -18,13 +19,19 @@
#include "common/event/libevent.h"
#include "common/event/libevent_scheduler.h"

#ifdef ENVOY_HANDLE_SIGNALS
#include "exe/signal_action.h"
#endif

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 CrashHandlerInterface {
public:
DispatcherImpl(Api::Api& api, Event::TimeSystem& time_system);
DispatcherImpl(Buffer::WatermarkFactoryPtr&& factory, Api::Api& api,
Expand Down Expand Up @@ -65,6 +72,20 @@ 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;
}

// CrashHandlerInterface
void crashHandler() const override {
if (isThreadSafe()) {
mattklein123 marked this conversation as resolved.
Show resolved Hide resolved
if (current_object_) {
current_object_->logState(std::cerr);
}
}
}

private:
void runPostCallbacks();
Expand All @@ -88,6 +109,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_{};
};

Expand Down
3 changes: 3 additions & 0 deletions source/common/http/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -174,6 +175,8 @@ envoy_cc_library(
"//source/common/common:empty_string",
"//source/common/common:enum_to_int",
"//source/common/common:linked_object",
"//source/common/common:log_state_utils",
"//source/common/common:scope_tracker",
"//source/common/common:utility_lib",
"//source/common/http/http1:codec_lib",
"//source/common/http/http2:codec_lib",
Expand Down
7 changes: 7 additions & 0 deletions source/common/http/conn_manager_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -416,6 +417,8 @@ 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<Network::Socket::Options>()) {
ScopeTrackerImpl scope(this, connection_manager_.read_callbacks_->connection().dispatcher());
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How did you pick the places where you setup the tracked scope? Can we document in comments somewhere? It seems like we should be potentially tracking the encode side as well? Filter continuations? Etc.? I wonder if there is some more generic way we could do this? Nothing immediately comes to mind but I figured I would throw it out there.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's in PR description - I'm going to do encode side (from the router filter) as well as alarms for L7 in follow-ups :-)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK sounds good.


connection_manager_.stats_.named_.downstream_rq_total_.inc();
connection_manager_.stats_.named_.downstream_rq_active_.inc();
if (connection_manager_.codec_->protocol() == Protocol::Http2) {
Expand Down Expand Up @@ -585,6 +588,7 @@ 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) {
ScopeTrackerImpl scope(this, connection_manager_.read_callbacks_->connection().dispatcher());
request_headers_ = std::move(headers);
if (Http::Headers::get().MethodValues.Head ==
request_headers_->Method()->value().getStringView()) {
Expand Down Expand Up @@ -881,6 +885,7 @@ void ConnectionManagerImpl::ActiveStream::decodeHeaders(ActiveStreamDecoderFilte
}

void ConnectionManagerImpl::ActiveStream::decodeData(Buffer::Instance& data, bool end_stream) {
ScopeTrackerImpl scope(this, connection_manager_.read_callbacks_->connection().dispatcher());
maybeEndDecode(end_stream);
stream_info_.addBytesReceived(data.length());

Expand All @@ -890,6 +895,7 @@ 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) {
ScopeTrackerImpl scope(this, connection_manager_.read_callbacks_->connection().dispatcher());
resetIdleTimer();

// If we previously decided to decode only the headers, do nothing here.
Expand Down Expand Up @@ -1029,6 +1035,7 @@ void ConnectionManagerImpl::ActiveStream::addDecodedData(ActiveStreamDecoderFilt
}

void ConnectionManagerImpl::ActiveStream::decodeTrailers(HeaderMapPtr&& trailers) {
ScopeTrackerImpl scope(this, connection_manager_.read_callbacks_->connection().dispatcher());
resetIdleTimer();
maybeEndDecode(true);
request_trailers_ = std::move(trailers);
Expand Down
Loading