http: dumping session state on the decode path #7390

alyssawilk · 2019-06-24T20:39:01Z

Adding per-stream pretty printing, and tracking the active stream when decoding data and dumping it on crash

If we like how this looks, I'll do the same for the encode path (track scope when entering the router) and add an optional scope tracker to alarms and plumb existing resumption alarms.

Risk Level: Medium
Testing: new unit tests, manual testing.
Docs Changes: n/a
Release Notes: n/a
Part of #7300

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

source/common/common/log_state_utils.h

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

htuch

Looks good structurally, I have a bunch of specific areas on the leafs we could tackle to make this a bit cleaner. Thanks.
/wait

include/envoy/common/scope_tracker.h

include/envoy/event/dispatcher.h

include/envoy/http/header_map.h

htuch · 2019-06-26T19:44:15Z

source/common/common/log_state_utils.h

+    os << spaces << #member ": ";                                                                  \
+    if ((member) != nullptr) {                                                                     \
+      os << "\n";                                                                                  \
+      (member)->logState(os, indent_level + 1);                                                    \


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.

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.

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.

htuch · 2019-06-26T19:52:38Z

source/exe/signal_action.cc

+
+ABSL_CONST_INIT static absl::Mutex failure_mutex(absl::kConstInit);
+using FailureFunctionList = std::list<const CrashHandlerInterface*>;
+ABSL_CONST_INIT std::atomic<FailureFunctionList*> crash_handlers{nullptr};


So, all the code here to me seems pretty problematic, but maybe there isn't a better way. We have mutexes, atomics with relaxed memory ordering, manual memory allocations, a singleton, etc. Oh my :)

One way we could be cleaner about this is to have a per-thread local optional signal handler for any signal. On a signal, the global handler will iterate over the list of threads and try and invoke the signal handler if registered.

Yeah, I'd started by trying to implement this as a single handler in the server, and doing the plumbing through to snag dispatcher state, and it was messy enough I thought this was cleaner. I think if we get to a point where more than one class wants to register signal handlers it'd might be cleaner to do a single entry point per thread but I think for now it's just moving the mess to a different location.

source/exe/signal_action.cc

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

htuch · 2019-06-27T14:12:50Z

I'm generally good with this modulo the wish to have better clarity on how significant the "no allocation during fatal handling" policy is, since it is the main constraint on the solution space here. Will leave it to @mattklein123 for review/merge.

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

alyssawilk · 2019-06-27T15:00:11Z

Yeah, checked in with other proxy devs and one of our kernel guys, and new/malloc in signal handlers is pretty bad form. Added more detail to the comments. FWIW cerr is not without risk either - I got a suggestion to switch to ABSL_RAW_LOG which looks like it'd be safer but I'm not sure how to pass that through the Envoy stack in a plausible way.

Both folks I checked with independently suggested proto arena as a viable compromise. I think it's a bit riskier than what we have mainly because I'm unfamiliar with how it works under the hood, but I think it's a pretty viable compromise where you get your structured data and I get my (trusting jeremy) minimal-to-no allocations.

I suspect (still trying to avoid memory allocations) that I'd have to write my own proto printer, but I don't think that's hard to do with the existing reflection, and it'd keep all the pretty printing ascii logic to a single utility function rather than a widely included set of macros.

WDYT?

htuch

LGTM, thanks for checking with folks. I do like the idea of protbuf arenas for future consideration.

alyssawilk · 2019-07-01T16:17:25Z

@mattklein123 I think this is ready for your pass then

mattklein123

Thanks, cool stuff and will definitely be useful. Flushing out some comments.

General question: I wonder if this behavior should be opt-in, opt-out, or have some type of compile control? The reason I ask is that there is some risk of doubt fault and I'm not sure if core dumps will be useful if that happens?

/wait

mattklein123 · 2019-07-01T19:38:49Z

include/envoy/common/scope_tracker.h

+
+/*
+ * A class for tracking the scope of work.
+ * Currently this is only used for best-effort tracking the any L7 stream doing


s/the any/any ?

include/envoy/event/dispatcher.h

mattklein123 · 2019-07-01T19:44:49Z

source/common/common/scope_tracker.h

+
+namespace Envoy {
+
+class ScopeTrackerImpl {


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

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

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.

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

mattklein123 · 2019-07-01T19:46:28Z

source/common/event/dispatcher_impl.cc

@@ -25,6 +25,10 @@

 #include "event2/event.h"

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


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?

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.

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

source/common/event/dispatcher_impl.h

mattklein123 · 2019-07-01T19:49:21Z

source/common/http/conn_manager_impl.cc

@@ -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());


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.

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 :-)

OK sounds good.

mattklein123 · 2019-07-01T19:51:03Z

source/exe/signal_action.cc

@@ -20,6 +46,14 @@ void SignalAction::sigHandler(int sig, siginfo_t* info, void* context) {
  }
  tracer.logTrace();

+  FailureFunctionList* list = fatal_error_handlers.exchange(nullptr, std::memory_order_relaxed);


Can you add some comments on why we are dealing with thread safety in this way?

mattklein123 · 2019-07-01T19:51:37Z

test/exe/signals_test.cc

+      "backtrace.*Segmentation fault");
+  SignalAction::removeFatalErrorHandler(handler);
+
+  /*  SignalAction actions;


source/common/common/dump_state_utils.h

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

alyssawilk

ok, I think I got all of your comments. Added a compile option since signals already had one, but do you think we should have DS style config as well?

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

mattklein123 · 2019-07-02T15:24:40Z

Added a compile option since signals already had one, but do you think we should have DS style config as well?

IMO compile time is probably fine and easier, but I don't feel strongly about it if you do.

mattklein123

Thanks looks great. 1 comment about build options, docs, etc.

/wait

mattklein123 · 2019-07-02T17:33:51Z

docs/root/intro/version_history.rst

@@ -35,6 +35,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 -DENVOY_SKIP_OBJECT_TRACE_ON_DUMP


Can we add a bazel config setting similar to https://github.com/envoyproxy/envoy/blob/master/bazel/BUILD#L98? And then also document here: https://github.com/envoyproxy/envoy/tree/master/bazel#disabling-optional-features? And maybe also define this in the compile time options CI build? Also, does disabling signal traces implicitly disable this? I think so but maybe I'm not reading the code correctly? If that's the case can we document that?

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

mattklein123

Very nice!

Harvey said to merge once reviewed

alyssawilk added 2 commits June 24, 2019 16:20

Basic logging functions

d260dcd

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

http: active session tracking, and crash logging on the request path

ac93703

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

htuch reviewed Jun 24, 2019

View reviewed changes

source/common/common/log_state_utils.h Outdated Show resolved Hide resolved

htuch requested a review from mattklein123 June 24, 2019 22:45

htuch assigned mattklein123 and htuch Jun 24, 2019

alyssawilk changed the title ~~WIP: http: dumping session state on the decode path~~ http: dumping session state on the decode path Jun 25, 2019

Fixing build, adding UT

e0c631d

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

alyssawilk force-pushed the dumpState branch from 8dec0fd to e0c631d Compare June 25, 2019 20:50

alyssawilk changed the title ~~http: dumping session state on the decode path~~ WIP: http: dumping session state on the decode path Jun 25, 2019

tidy + more tests

b17c382

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

alyssawilk changed the title ~~WIP: http: dumping session state on the decode path~~ http: dumping session state on the decode path Jun 26, 2019

htuch previously requested changes Jun 26, 2019

View reviewed changes

repokitteh-read-only bot added the waiting label Jun 26, 2019

alyssawilk added 2 commits June 26, 2019 17:19

reviewer comments

4939235

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

Merge branch 'master' into dumpState

e5c0d31

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

repokitteh-read-only bot removed the waiting label Jun 26, 2019

more detail

ce554b7

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

htuch reviewed Jun 27, 2019

View reviewed changes

mattklein123 requested changes Jul 1, 2019

View reviewed changes

repokitteh-read-only bot added the waiting label Jul 1, 2019

some comments: still no config guards

42e27ba

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

repokitteh-read-only bot removed the waiting label Jul 1, 2019

mattklein123 added the waiting label Jul 1, 2019

renames, file moves, relnotes, build flags

41d620a

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

repokitteh-read-only bot removed the waiting label Jul 2, 2019

alyssawilk commented Jul 2, 2019

View reviewed changes

speeling

e8bbe34

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

mattklein123 requested changes Jul 2, 2019

View reviewed changes

repokitteh-read-only bot added the waiting label Jul 2, 2019

better compile config

56ccb5a

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

repokitteh-read-only bot removed the waiting label Jul 2, 2019

Merge branch 'master' into dumpState

510534e

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

mattklein123 added the waiting label Jul 2, 2019

alyssawilk added 2 commits July 3, 2019 11:34

Merge branch 'master' into dumpState

9e31cd1

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

hopefully fixing build/copt inversion

f0b1519

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

repokitteh-read-only bot removed the waiting label Jul 3, 2019

mattklein123 approved these changes Jul 3, 2019

View reviewed changes

mattklein123 merged commit 733052a into envoyproxy:master Jul 3, 2019

alyssawilk deleted the dumpState branch July 31, 2019 20:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http: dumping session state on the decode path #7390

http: dumping session state on the decode path #7390

alyssawilk commented Jun 24, 2019 •

edited

Loading

htuch left a comment

htuch Jun 26, 2019

alyssawilk Jun 26, 2019

htuch Jun 27, 2019

htuch Jun 26, 2019

alyssawilk Jun 26, 2019

htuch commented Jun 27, 2019

alyssawilk commented Jun 27, 2019

htuch left a comment

alyssawilk commented Jul 1, 2019

mattklein123 left a comment

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

alyssawilk Jul 1, 2019

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

alyssawilk Jul 1, 2019

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

alyssawilk Jul 1, 2019

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

mattklein123 Jul 1, 2019

alyssawilk left a comment

mattklein123 commented Jul 2, 2019

mattklein123 left a comment

mattklein123 Jul 2, 2019

mattklein123 left a comment

http: dumping session state on the decode path #7390

http: dumping session state on the decode path #7390

Conversation

alyssawilk commented Jun 24, 2019 • edited Loading

htuch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

htuch commented Jun 27, 2019

alyssawilk commented Jun 27, 2019

htuch left a comment

Choose a reason for hiding this comment

alyssawilk commented Jul 1, 2019

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alyssawilk left a comment

Choose a reason for hiding this comment

mattklein123 commented Jul 2, 2019

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattklein123 left a comment

Choose a reason for hiding this comment

alyssawilk commented Jun 24, 2019 •

edited

Loading