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() = default;

/**
* 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 {
using IterateData = std::pair<std::ostream*, const char*>;
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<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
16 changes: 16 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,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"],
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
9 changes: 8 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,13 @@ envoy_cc_library(
"//include/envoy/network:connection_handler_interface",
"//source/common/common:minimal_logger_lib",
"//source/common/common:thread_lib",
],
"//source/exe:crash_handler_lib",
] + select({
"//bazel:disable_signal_trace": [],
"//conditions:default": [
"//source/exe:sigaction_lib",
],
}),
)

envoy_cc_library(
Expand Down
24 changes: 19 additions & 5 deletions source/common/event/dispatcher_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,10 @@

#include "event2/event.h"

#ifdef ENVOY_HANDLE_SIGNALS
#include "exe/signal_action.h"
Copy link
Member

Choose a reason for hiding this comment

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

Reaching into exe here seems wrong from a layering perspective. Would it be better to have some other type of injected interface for this purpose?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

for layering, honestly I'd think all of the signal handling code could be moved out of exe since we use it in test, so it's somewhat core to the server handling. maybe source/server/signal/?

I'm also not sure if that addresses your concerns, or if you still think there's value in the dispatcher not reaching directly to signal handling code.

Copy link
Member

Choose a reason for hiding this comment

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

sgtm regarding moving. I might even go as far as to move some of it into source/common/signal but up to you.

#endif

namespace Envoy {
namespace Event {

Expand All @@ -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::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 Expand Up @@ -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);
}
Expand Down
23 changes: 22 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,17 @@
#include "common/event/libevent.h"
#include "common/event/libevent_scheduler.h"

#include "exe/crash_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 CrashHandlerInterface {
public:
DispatcherImpl(Api::Api& api, Event::TimeSystem& time_system);
DispatcherImpl(Buffer::WatermarkFactoryPtr&& factory, Api::Api& api,
Expand Down Expand Up @@ -65,8 +70,23 @@ 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:
TimerPtr createTimerInternal(TimerCb cb);
void runPostCallbacks();

// Validate that an operation is thread safe, i.e. it's invoked on the same thread that the
Expand All @@ -88,6 +108,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
Loading