debug: improving stack traces by alyssawilk · Pull Request #3558 · envoyproxy/envoy

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 <alyssar@chromium.org>

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

+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 <alyssar@chromium.org>

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

+        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

                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

 #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

-    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 <alyssar@chromium.org>

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

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

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

    // 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

@@ -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

  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 <alyssar@chromium.org>

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

  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 <alyssar@chromium.org>

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 <ggreenway@apple.com>

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 <ggreenway@apple.com>

improving stack traces

1a93e88

Signed-off-by: Alyssa Wilk <alyssar@chromium.org>

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 <alyssar@chromium.org>

fixing apple build

85e82bf

Signed-off-by: Alyssa Wilk <alyssar@chromium.org>

PiotrSikora suggested changes Jun 6, 2018

View reviewed changes

reviewer comments

319e71d

Signed-off-by: Alyssa Wilk <alyssar@chromium.org>

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 <alyssar@chromium.org>

fixing format

b968dab

Signed-off-by: Alyssa Wilk <alyssar@chromium.org>

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 <alyssar@chromium.org>

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

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

Conversation

alyssawilk commented Jun 6, 2018

Uh oh!

alyssawilk commented Jun 6, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PiotrSikora Jun 6, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zuercher commented Jun 6, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PiotrSikora commented Jun 6, 2018

Uh oh!

alyssawilk commented Jun 6, 2018

Uh oh!

PiotrSikora commented Jun 6, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

PiotrSikora left a comment

Choose a reason for hiding this comment

Uh oh!

PiotrSikora left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

PiotrSikora Jun 6, 2018 •

edited

Loading

zuercher commented Jun 6, 2018 •

edited

Loading