debug: improving stack traces #3558

alyssawilk · 2018-06-06T14:54:38Z

Dumping function names in stack traces where absl::Sybolize is supported.

before: https://pastebin.com/raw/kZihnpSK
after: https://pastebin.com/raw/XcDwcx15

Risk Level: Low (worst case someone gets a borked stack trace and we roll back)
Testing: manual: see pastebin links.
Docs Changes: updated current docs on stack traces
Release Notes: inline.

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

alyssawilk · 2018-06-06T14:55:24Z

@zuercher want me to do the same thing on the APPLE path? I'm wary of making changes there since I can't test them.

htuch · 2018-06-06T14:59:27Z

bazel/README.md

+actions like segfaults. Where supported, stack traces will contain resolved
+symbols. On systems where absl::Symbolization is not supported, the stack
+traces written in the log or to stderr contain addresses rather than resolved symbols.
+The `tools/stack_decode.py` script exists to process the output and do symbol resolution


Do we still support stack_decode.py where absl::Symbolization is supported? I think the former gives you line numbers..

The former didn't work at all for me (despite copy-pasting all the various tags from the instructions) which is why I finally got around to doing it inline.

Are you requesting a mode where we disable it? I could add a flag.

I'm more curious if you can use both together.. Is the absl:: approach able to extract line numbers when we compile -c dbg? That would totally obviate stack_decode.py.

Unfortunately the traces I posted were with -c dbg so I'm going to go with "no"

I've already tracked down the guy who made these changes in absl, so I can go ask them if they're planning on enhancements. Meanwhile I've made it so stack decode works as well as it has, which is to say not at all for me, but I'm fairly confident it will no longer regress for those who get useful output from it. Before my PR I'd get something of the form
https://pastebin.com/x1KWJjFg
and with my PR and without the latest push it was like
https://pastebin.com/23KrqEmT
witht he latest push it's back to the former #1 ?? ??:0 output which is as much as I can verify :-/

Yeah, ./tools/stack_decode.py seems to be broken, and I can't get anything out of it.

@alyssawilk Your "good" output is actually output from absl::Symbolize() that wasn't matched against any regex and left as-is. The ./tools/stack_decode.py output starts with Backtrace (most recent call first) from thread 0:.

zuercher · 2018-06-06T15:48:33Z

@alyssawilk I'm out most of today or I'd pull it and give it a try. If you're ready to merge before I get a chance, go ahead and merge without __APPLE__ and I'll make a separate PR if it works.

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

PiotrSikora · 2018-06-06T19:59:59Z

source/server/backtrace.h

+        ENVOY_LOG(critical, "thr<{}> #{} {} {}", thread_id, stack_trace_[i].idx,
+                  stack_trace_[i].addr, out);
+      } else {
+        ENVOY_LOG(critical, "thr<{}> #{} (unknown)", thread_id, stack_trace_[i].idx,


This should be "thr<{}> #{} {} (unknown)" (missing one {}).

PiotrSikora · 2018-06-06T20:00:12Z

source/server/backtrace.h

@@ -104,7 +109,14 @@ class BackwardsTrace : Logger::Loggable<Logger::Id::backtrace> {
      ENVOY_LOG(critical, "thr<{}> #{} {}: {}", thread_id, stack_trace_[i].idx,
                stack_trace_[i].addr, trace.object_function);
 #else
-      ENVOY_LOG(critical, "thr<{}> #{} {}", thread_id, stack_trace_[i].idx, stack_trace_[i].addr);
+


Nit: extra empty line.

PiotrSikora · 2018-06-06T20:00:29Z

source/server/backtrace.h

@@ -104,7 +109,14 @@ class BackwardsTrace : Logger::Loggable<Logger::Id::backtrace> {
      ENVOY_LOG(critical, "thr<{}> #{} {}: {}", thread_id, stack_trace_[i].idx,
                stack_trace_[i].addr, trace.object_function);
 #else
-      ENVOY_LOG(critical, "thr<{}> #{} {}", thread_id, stack_trace_[i].idx, stack_trace_[i].addr);
+
+      if (absl::Symbolize(stack_trace_[i].addr, out, 200)) {


Nit: use sizeof(out) instead of 200.

PiotrSikora · 2018-06-06T20:05:46Z

source/server/backtrace.h

-    ENVOY_LOG(critical, "Backtrace obj<{}> thr<{}> (use tools/stack_decode.py):", obj_name,
+    char out[200];
+    ENVOY_LOG(critical,
+              "Backtrace obj<{}> thr<{}> (If unsymbolized, use tools/stack_decode.py):", obj_name,


While you're here, should we perhaps flip the order from "Backtrace obj<{}> thr<{}> ..." to "Backtrace thr<{}> obj<{}> ..." to match rest of the output?

PiotrSikora · 2018-06-06T20:11:40Z

@alyssawilk @zuercher I'm going to test if this works on macOS (but it's going to take a while, since I'm on dual-core machine).

alyssawilk · 2018-06-06T20:33:15Z

Looks like macos is already has better stack trace support than I'm adding so I think we're set here.

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

PiotrSikora · 2018-06-06T20:37:19Z

It doesn't work on macOS, it only emits lines with (unknown).

PiotrSikora · 2018-06-06T20:57:44Z

source/server/backtrace.h

@@ -84,14 +86,17 @@ class BackwardsTrace : Logger::Loggable<Logger::Id::backtrace> {
 #ifdef __APPLE__
    // The stack_decode.py script uses addr2line which isn't readily available and doesn't seem to
    // work when installed.
-    ENVOY_LOG(critical, "Backtrace obj<{}> thr<{}>:", obj_name, thread_id);
+    ENVOY_LOG(critical, "Backtrace thr<{}> obj<{}>:", thread_id, obj_name);


You need to update tools/stack_decode.py for that, sorry!

diff --git a/tools/stack_decode.py b/tools/stack_decode.py index f141d1c1..2edbc63e 100755 --- a/tools/stack_decode.py +++ b/tools/stack_decode.py @@ -29,7 +29,7 @@ def decode_stacktrace_log(input_source): # bazel-out/local-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:84] backtrace_marker = "\[backtrace\] [^\s]+" trace_begin_re = re.compile( - "^(.+)%s Backtrace obj<(.+)> thr<(\d+)" % backtrace_marker) + "^(.+)%s Backtrace thr<(\d+)> obj<(.+)>" % backtrace_marker) stackaddr_re = re.compile("%s thr<(\d+)> #\d+ (0x[0-9a-fA-F]+) " % backtrace_marker) new_object_re = re.compile("%s thr<(\d+)> obj<(.+)>$" % backtrace_marker) trace_end_re = re.compile("%s end backtrace thread (\d+)" % backtrace_marker) @@ -42,7 +42,7 @@ def decode_stacktrace_log(input_source): return # EOF begin_trace_match = trace_begin_re.search(line) if begin_trace_match: - log_prefix, objfile, thread_id = begin_trace_match.groups() + log_prefix, thread_id, objfile = begin_trace_match.groups() traces[thread_id] = Backtrace(log_prefix=log_prefix, obj_list=[]) traces[thread_id].obj_list.append( AddressList(obj_file=objfile, addresses=[]))

PiotrSikora · 2018-06-06T21:26:17Z

source/server/backtrace.h

@@ -104,7 +109,13 @@ class BackwardsTrace : Logger::Loggable<Logger::Id::backtrace> {
      ENVOY_LOG(critical, "thr<{}> #{} {}: {}", thread_id, stack_trace_[i].idx,


Nit: we're emitting "thr<{}> #{} {}: {}" on macOS and ""thr<{}> #{} {} {}" (without :) on Linux.

Consider removing : from macOS output or adding it to both Linux outputs.

PiotrSikora · 2018-06-06T21:26:35Z

tools/stack_decode.py

@@ -30,7 +30,7 @@ def decode_stacktrace_log(input_source):
  backtrace_marker = "\[backtrace\] [^\s]+"
  trace_begin_re = re.compile(
      "^(.+)%s Backtrace obj<(.+)> thr<(\d+)" % backtrace_marker)
-  stackaddr_re = re.compile("%s thr<(\d+)> #\d+ (0x[0-9a-fA-F]+)$" % backtrace_marker)
+  stackaddr_re = re.compile("%s thr<(\d+)> #\d+ (0x[0-9a-fA-F]+) " % backtrace_marker)


Nit: the space at the end is unnecessary here.

I never trust regex to be greedy so I'm more comfortable leaving it in

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

PiotrSikora · 2018-06-07T20:52:30Z

tools/stack_decode.py

@@ -29,8 +29,8 @@ def decode_stacktrace_log(input_source):
  # bazel-out/local-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:84]
  backtrace_marker = "\[backtrace\] [^\s]+"
  trace_begin_re = re.compile(
-      "^(.+)%s Backtrace obj<(.+)> thr<(\d+)" % backtrace_marker)
-  stackaddr_re = re.compile("%s thr<(\d+)> #\d+ (0x[0-9a-fA-F]+)$" % backtrace_marker)
+      "^(.+)%s Backtrace thr<(\d+).*obj<(.+)>" % backtrace_marker)


Any particular reason for using "thr<(\d+).*obj<(.+)>" instead of "thr<(\d+)> obj<(.+)>"? We know exactly the format that's emitted.

PiotrSikora

One small nit, but LGTM otherwise.

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

PiotrSikora

Thanks!

This fixes an ASAN failure when run in a certain environment, as described by abseil/abseil-cpp#118. The failure was added by envoyproxy#3558, which pulled in the same static initializer as described in the original absl issue linked here. Signed-off-by: Greg Greenway <[email protected]>

This fixes an ASAN failure when run in a certain environment, as described by abseil/abseil-cpp#118. The failure was added by #3558, which pulled in the same static initializer as described in the original absl issue linked here. Signed-off-by: Greg Greenway <[email protected]>

improving stack traces

1a93e88

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

htuch reviewed Jun 6, 2018

View reviewed changes

alyssawilk added 2 commits June 6, 2018 12:00

Allowing both inline and python back trace

9941ddc

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

fixing apple build

85e82bf

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

PiotrSikora suggested changes Jun 6, 2018

View reviewed changes

reviewer comments

319e71d

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

PiotrSikora reviewed Jun 6, 2018

View reviewed changes

PiotrSikora suggested changes Jun 6, 2018

View reviewed changes

alyssawilk added 2 commits June 7, 2018 11:40

reviewer comments, fixing backtrace regex

62aa224

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

fixing format

b968dab

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

PiotrSikora reviewed Jun 7, 2018

View reviewed changes

PiotrSikora previously approved these changes Jun 7, 2018

View reviewed changes

being unlazy

c0d3750

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

alyssawilk dismissed PiotrSikora’s stale review via c0d3750 June 7, 2018 20:57

PiotrSikora approved these changes Jun 7, 2018

View reviewed changes

mattklein123 approved these changes Jun 8, 2018

View reviewed changes

mattklein123 merged commit cd05980 into envoyproxy:master Jun 8, 2018

ggreenway mentioned this pull request Jun 11, 2018

Upgrade absl. #3591

Merged

alyssawilk deleted the symbolize branch October 10, 2018 19:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

debug: improving stack traces #3558

debug: improving stack traces #3558

alyssawilk commented Jun 6, 2018

alyssawilk commented Jun 6, 2018

htuch Jun 6, 2018

alyssawilk Jun 6, 2018

htuch Jun 6, 2018

alyssawilk Jun 6, 2018

PiotrSikora Jun 6, 2018 •

edited

Loading

zuercher commented Jun 6, 2018 •

edited

Loading

PiotrSikora Jun 6, 2018

PiotrSikora Jun 6, 2018

PiotrSikora Jun 6, 2018

PiotrSikora Jun 6, 2018

PiotrSikora commented Jun 6, 2018

alyssawilk commented Jun 6, 2018

PiotrSikora commented Jun 6, 2018

PiotrSikora Jun 6, 2018

PiotrSikora Jun 6, 2018

PiotrSikora Jun 6, 2018

alyssawilk Jun 7, 2018

PiotrSikora Jun 7, 2018

PiotrSikora left a comment

PiotrSikora left a comment

		@@ -104,7 +109,13 @@ class BackwardsTrace : Logger::Loggable<Logger::Id::backtrace> {
		ENVOY_LOG(critical, "thr<{}> #{} {}: {}", thread_id, stack_trace_[i].idx,

debug: improving stack traces #3558

debug: improving stack traces #3558

Conversation

alyssawilk commented Jun 6, 2018

alyssawilk commented Jun 6, 2018

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

PiotrSikora Jun 6, 2018 • edited Loading

Choose a reason for hiding this comment

zuercher commented Jun 6, 2018 • edited Loading

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

PiotrSikora commented Jun 6, 2018

alyssawilk commented Jun 6, 2018

PiotrSikora commented Jun 6, 2018

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

PiotrSikora left a comment

Choose a reason for hiding this comment

PiotrSikora left a comment

Choose a reason for hiding this comment

PiotrSikora Jun 6, 2018 •

edited

Loading

zuercher commented Jun 6, 2018 •

edited

Loading