From 80a06850ee02f52a462f4661e2e9fbbf4e0a7d3d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Fri, 25 Jan 2019 16:04:07 -0500 Subject: [PATCH 1/8] Replace "backward" stack trace with absl::Stacktrace. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Use the absl::Stacktrace library along with absl::Symbolize to generate symbolized stack traces without requiring any external tool or post processing. Remove the external dependency on "backward" library. This deprecates stack_decode.py, which is removed. References to the stack_decode.py process are removed from README. Signed-off-by: Dan Noé --- bazel/README.md | 18 +----- bazel/repositories.bzl | 15 ++--- bazel/repository_locations.bzl | 5 -- source/exe/signal_action.cc | 27 +-------- source/server/BUILD | 2 +- source/server/backtrace.h | 97 +++++++++--------------------- tools/BUILD | 1 - tools/stack_decode.py | 107 --------------------------------- 8 files changed, 36 insertions(+), 236 deletions(-) delete mode 100755 tools/stack_decode.py diff --git a/bazel/README.md b/bazel/README.md index 5d16c0c7df0ec..78cbf44abbadb 100644 --- a/bazel/README.md +++ b/bazel/README.md @@ -187,23 +187,7 @@ Envoy can produce backtraces on demand and from assertions and other fatal actions like segfaults. Where supported, stack traces will contain resolved symbols, though not include line numbers. 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 including line numbers, to make the stack traces useful. -Any log lines not relevant to the backtrace capability -are passed through the script unchanged (it acts like a filter). - -The script runs in one of two modes. If passed no arguments it anticipates -Envoy (or test) output on stdin. You can postprocess a log or pipe the output of -an Envoy process. If passed some arguments it runs the arguments as a child -process. This enables you to run a test with backtrace post processing. Bazel -sandboxing must be disabled by specifying standalone execution. Example -command line: - -``` -bazel test -c dbg //test/server:backtrace_test ---run_under=`pwd`/tools/stack_decode.py --strategy=TestRunner=standalone ---cache_test_results=no --test_output=all -``` +than resolved symbols. You will need to use either a `dbg` build type or the `opt` build type to get symbol information in the binaries. diff --git a/bazel/repositories.bzl b/bazel/repositories.bzl index c3c8bb2535ea6..f565bf7a007bb 100644 --- a/bazel/repositories.bzl +++ b/bazel/repositories.bzl @@ -279,7 +279,6 @@ def envoy_dependencies(path = "@envoy_deps//", skip_targets = []): # semi-standard in the Bazel community, intended to avoid both duplicate # dependencies and name conflicts. _com_google_absl() - _com_github_bombela_backward() _com_github_circonus_labs_libcircllhist() _com_github_cyan4973_xxhash() _com_github_eile_tclap() @@ -321,16 +320,6 @@ def _boringssl_fips(): build_file = "@envoy//bazel/external:boringssl_fips.BUILD", ) -def _com_github_bombela_backward(): - _repository_impl( - name = "com_github_bombela_backward", - build_file = "@envoy//bazel/external:backward.BUILD", - ) - native.bind( - name = "backward", - actual = "@com_github_bombela_backward//:backward", - ) - def _com_github_circonus_labs_libcircllhist(): _repository_impl( name = "com_github_circonus_labs_libcircllhist", @@ -529,6 +518,10 @@ def _com_google_absl(): name = "abseil_symbolize", actual = "@com_google_absl//absl/debugging:symbolize", ) + native.bind( + name = "abseil_stacktrace", + actual = "@com_google_absl//absl/debugging:stacktrace", + ) # Require abseil_time as an indirect dependency as it is needed by the # direct dependency jwt_verify_lib. diff --git a/bazel/repository_locations.bzl b/bazel/repository_locations.bzl index 0823117e4fb5b..2a80f5b306173 100644 --- a/bazel/repository_locations.bzl +++ b/bazel/repository_locations.bzl @@ -26,11 +26,6 @@ REPOSITORY_LOCATIONS = dict( strip_prefix = "thrift-0.11.0", urls = ["https://files.pythonhosted.org/packages/c6/b4/510617906f8e0c5660e7d96fbc5585113f83ad547a3989b80297ac72a74c/thrift-0.11.0.tar.gz"], ), - com_github_bombela_backward = dict( - sha256 = "ad73be31c5cfcbffbde7d34dba18158a42043a109e7f41946f0b0abd589ed55e", - strip_prefix = "backward-cpp-1.4", - urls = ["https://github.com/bombela/backward-cpp/archive/v1.4.tar.gz"], - ), com_github_circonus_labs_libcircllhist = dict( sha256 = "9949e2864b8ad00ee5c3e9c1c3c01e51b6b68bb442a919652fc66b9776477987", strip_prefix = "libcircllhist-fd8a14463739d247b414825cc56ca3946792a3b9", diff --git a/source/exe/signal_action.cc b/source/exe/signal_action.cc index 793d719643c3d..5ff87da9ccbdd 100644 --- a/source/exe/signal_action.cc +++ b/source/exe/signal_action.cc @@ -9,32 +9,11 @@ namespace Envoy { constexpr int SignalAction::FATAL_SIGS[]; void SignalAction::sigHandler(int sig, siginfo_t* info, void* context) { - void* error_pc = 0; - - const ucontext_t* ucontext = reinterpret_cast(context); - if (ucontext != nullptr) { -#ifdef REG_RIP - // x86_64 - error_pc = reinterpret_cast(ucontext->uc_mcontext.gregs[REG_RIP]); -#elif defined(__APPLE__) && defined(__x86_64__) - error_pc = reinterpret_cast(ucontext->uc_mcontext->__ss.__rip); -#elif defined(__powerpc__) - error_pc = reinterpret_cast(ucontext->uc_mcontext.regs->nip); -#elif defined(__aarch64__) - error_pc = reinterpret_cast(ucontext->uc_mcontext.pc); -#elif defined(__arm__) - error_pc = reinterpret_cast(ucontext->uc_mcontext.arm_pc); -#else -#warning "Please enable and test PC retrieval code for your arch in signal_action.cc" -// x86 Classic: reinterpret_cast(ucontext->uc_mcontext.gregs[REG_EIP]); -// ARM: reinterpret_cast(ucontext->uc_mcontext.arm_pc); -#endif - } - BackwardsTrace tracer; + tracer.logFault(strsignal(sig), info->si_addr); - if (error_pc != 0) { - tracer.captureFrom(error_pc); + if (context != nullptr) { + tracer.captureFrom(context); } else { tracer.capture(); } diff --git a/source/server/BUILD b/source/server/BUILD index 3220b5d2f3609..34574be7ded66 100644 --- a/source/server/BUILD +++ b/source/server/BUILD @@ -13,7 +13,7 @@ envoy_cc_library( name = "backtrace_lib", hdrs = ["backtrace.h"], external_deps = [ - "backward", + "abseil_stacktrace", "abseil_symbolize", ], tags = ["backtrace"], diff --git a/source/server/backtrace.h b/source/server/backtrace.h index 24eb010436a3b..b2645c8a70bb3 100644 --- a/source/server/backtrace.h +++ b/source/server/backtrace.h @@ -1,9 +1,8 @@ #pragma once -#include - #include "common/common/logger.h" +#include "absl/debugging/stacktrace.h" #include "absl/debugging/symbolize.h" namespace Envoy { @@ -15,7 +14,7 @@ namespace Envoy { } while (0) /** - * Use the Backward library ( https://github.com/bombela/backward-cpp ) to log + * Use absl::Stacktrace and absl::Symbolize to log resolved symbols * stack traces on demand. To use this just do: * * BackwardsTrace tracer; @@ -29,20 +28,8 @@ namespace Envoy { * For convenience a macro is provided BACKTRACE_LOG() which performs the * construction, capture, and log in one shot. * - * To resolve the addresses in the backtrace output and de-interleave - * multithreaded output use the tools/stack_decode.py command and pass the - * log/stderr output to stdin of the tool. Backtrace lines will be resolved, - * other lines will be passed through and echo'd unchanged. - * - * The stack_decode.py tool can also run envoy or a test as a child process if - * you pass the command and arguments as arguments to the tool. This enables - * you to run tests containing backtrace commands added for debugging and see - * the output like this: - * - * bazel test -c dbg //test/server:backtrace_test - * --run_under=`pwd`/tools/stack_decode.py - * --strategy=TestRunner=standalone --cache_test_results=no - * --test_output=all + * If the symbols cannot be resolved by absl::Symbolize then the raw address + * will be printed instead. */ class BackwardsTrace : Logger::Loggable { public: @@ -53,72 +40,41 @@ class BackwardsTrace : Logger::Loggable { * * The trace will begin with the call to capture(). */ - void capture() { stack_trace_.load_here(MAX_STACK_DEPTH); } + void capture() { + // Skip of one means we exclude the last call, which must be to capture(). + stack_depth_ = absl::GetStackTrace(stack_trace_, MAX_STACK_DEPTH, /* skip_count = */ 1); + } /** - * Capture a stack trace from a particular address. + * Capture a stack trace from a particular context. * * This can be used to capture a useful stack trace from a fatal signal - * handler. + * handler. The context argument should be a pointer to the context passed + * to a signal handler registered via a sigaction struct. * - * @param address The stack trace will begin from this address. + * @param context A pointer to ucontext_t obtained from a sigaction handler. */ - void captureFrom(void* address) { stack_trace_.load_from(address, MAX_STACK_DEPTH); } + void captureFrom(const void* context) { + stack_depth_ = + absl::GetStackTraceWithContext(stack_trace_, MAX_STACK_DEPTH, /* skip_count = */ 1, context, + /* min_dropped_frames = */ nullptr); + } /** * Log the stack trace. */ void logTrace() { - backward::TraceResolver resolver; - resolver.load_stacktrace(stack_trace_); - // If there's nothing in the captured trace we cannot do anything. - // The size must be at least two for useful info - there is a sentinel frame - // at the end that we ignore. - if (stack_trace_.size() < 2) { - ENVOY_LOG(critical, "Back trace attempt failed"); - return; - } - - const auto thread_id = stack_trace_.thread_id(); - backward::ResolvedTrace first_frame_trace = resolver.resolve(stack_trace_[0]); - auto obj_name = first_frame_trace.object_filename; - -#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 thr<{}> obj<{}>:", thread_id, obj_name); -#else - char out[200]; - ENVOY_LOG(critical, - "Backtrace thr<{}> obj<{}> (If unsymbolized, use tools/stack_decode.py):", thread_id, - obj_name); -#endif - - // Backtrace gets tagged by ASAN when we try the object name resolution for the last - // frame on stack, so skip the last one. It has no useful info anyway. - - for (unsigned int i = 0; i < stack_trace_.size() - 1; ++i) { - backward::ResolvedTrace trace = resolver.resolve(stack_trace_[i]); - if (trace.object_filename != obj_name) { - obj_name = trace.object_filename; - ENVOY_LOG(critical, "thr<{}> obj<{}>", thread_id, obj_name); - } + ENVOY_LOG(critical, "Backtrace:"); -#ifdef __APPLE__ - // In the absence of stack_decode.py, print the function name. - ENVOY_LOG(critical, "thr<{}> #{} {} {}", thread_id, stack_trace_[i].idx, stack_trace_[i].addr, - trace.object_function); -#else - if (absl::Symbolize(stack_trace_[i].addr, out, sizeof(out))) { - ENVOY_LOG(critical, "thr<{}> #{} {} {}", thread_id, stack_trace_[i].idx, - stack_trace_[i].addr, out); + for (int i = 0; i < stack_depth_; ++i) { + char out[1024]; + const bool success = absl::Symbolize(stack_trace_[i], out, sizeof(out)); + if (success) { + ENVOY_LOG(critical, "#{}: {}", i, out); } else { - ENVOY_LOG(critical, "thr<{}> #{} {} (unknown)", thread_id, stack_trace_[i].idx, - stack_trace_[i].addr); + ENVOY_LOG(critical, "#{}: {}", i, stack_trace_[i]); } -#endif } - ENVOY_LOG(critical, "end backtrace thread {}", stack_trace_.thread_id()); } void logFault(const char* signame, const void* addr) { @@ -126,7 +82,8 @@ class BackwardsTrace : Logger::Loggable { } private: - static const int MAX_STACK_DEPTH = 64; - backward::StackTrace stack_trace_; + static constexpr int MAX_STACK_DEPTH = 64; + void* stack_trace_[MAX_STACK_DEPTH]; + int stack_depth_; }; } // namespace Envoy diff --git a/tools/BUILD b/tools/BUILD index 6f5b42ef0a562..6471ce3d51218 100644 --- a/tools/BUILD +++ b/tools/BUILD @@ -11,7 +11,6 @@ envoy_package() exports_files([ "gen_git_sha.sh", - "stack_decode.py", "check_format.py", "header_order.py", "envoy_build_fixer.py", diff --git a/tools/stack_decode.py b/tools/stack_decode.py deleted file mode 100755 index 6d05ab842090d..0000000000000 --- a/tools/stack_decode.py +++ /dev/null @@ -1,107 +0,0 @@ -#!/usr/bin/env python - -# Call addr2line as needed to resolve addresses in a stack trace, -# de-interleaving the log lines from multiple threads if required. -# -# Two ways to call: -# 1) No arguments means this script will treat stdin as log output from -# Envoy -# 2) Some arguments means run a subprocess with that command line and send -# stderr through the script -# -# In each case this script will decode any backtrace log lines found and echo -# back all non-Backtrace lines untouched. - -import collections -import re -import subprocess -import sys - -Backtrace = collections.namedtuple("Backtrace", "log_prefix obj_list") -AddressList = collections.namedtuple("AddressList", "obj_file addresses") - - -# Process the log output looking for stacktrace snippets, print them out once -# the entire stack trace has been read. End when EOF received. -def decode_stacktrace_log(input_source): - traces = {} - # Match something like [backtrace] - # 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 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) - - # build a dictionary indexed by thread_id, value is a Backtrace namedtuple - try: - while True: - line = input_source.readline() - if line == "": - return # EOF - begin_trace_match = trace_begin_re.search(line) - if begin_trace_match: - 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=[])) - continue - stackaddr_match = stackaddr_re.search(line) - if stackaddr_match: - thread_id, address = stackaddr_match.groups() - traces[thread_id].obj_list[-1].addresses.append(address) - continue - new_object_match = new_object_re.search(line) - if new_object_match: - thread_id, newobj = new_object_match.groups() - traces[thread_id].obj_list.append(AddressList(obj_file=newobj, addresses=[])) - continue - trace_end_match = trace_end_re.search(line) - if trace_end_match: - thread_id = trace_end_match.groups()[0] - output_stacktrace(thread_id, traces[thread_id]) - else: - # Pass through print all other log lines: - sys.stdout.write(line) - except KeyboardInterrupt: - return - - -# Execute addr2line with a particular object file and input string of addresses -# to resolve, one per line. -# -# Returns list of result lines -def run_addr2line(obj_file, piped_input): - addr2line = subprocess.Popen(["addr2line", "-Cpisfe", obj_file], - stdin=subprocess.PIPE, - stdout=subprocess.PIPE) - output_stdout, _ = addr2line.communicate(piped_input) - return output_stdout.split("\n") - - -# Output one stacktrace after passing it through addr2line with appropriate -# options -def output_stacktrace(thread_id, traceinfo): - output_lines = [] - for address_list in traceinfo.obj_list: - piped_input = "" - obj_name = address_list.obj_file - for stack_addr in address_list.addresses: - piped_input += (stack_addr + "\n") - output_lines += run_addr2line(obj_name, piped_input) - - resolved_stack_frames = enumerate(output_lines, start=1) - sys.stdout.write( - "%s Backtrace (most recent call first) from thread %s:\n" % (traceinfo.log_prefix, thread_id)) - for stack_frame in resolved_stack_frames: - sys.stdout.write(" #%s %s\n" % stack_frame) - - -if __name__ == "__main__": - if len(sys.argv) > 1: - rununder = subprocess.Popen(sys.argv[1:], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) - decode_stacktrace_log(rununder.stdout) - rununder.wait() - sys.exit(rununder.returncode) # Pass back test pass/fail result - else: - decode_stacktrace_log(sys.stdin) - sys.exit(0) From 55728686404a634c6e3d1c9cd0f74c17d324d03a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Mon, 28 Jan 2019 09:36:23 -0500 Subject: [PATCH 2/8] Switch to new style constant, fix initialization bug. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit stack_depth_ wasn't zero initialized, it should be to make attempts to log a trace without first capturing a trace safe. Signed-off-by: Dan Noé --- source/server/backtrace.h | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/source/server/backtrace.h b/source/server/backtrace.h index b2645c8a70bb3..67b0afe20fc52 100644 --- a/source/server/backtrace.h +++ b/source/server/backtrace.h @@ -42,7 +42,7 @@ class BackwardsTrace : Logger::Loggable { */ void capture() { // Skip of one means we exclude the last call, which must be to capture(). - stack_depth_ = absl::GetStackTrace(stack_trace_, MAX_STACK_DEPTH, /* skip_count = */ 1); + stack_depth_ = absl::GetStackTrace(stack_trace_, MaxStackDepth, /* skip_count = */ 1); } /** @@ -56,7 +56,7 @@ class BackwardsTrace : Logger::Loggable { */ void captureFrom(const void* context) { stack_depth_ = - absl::GetStackTraceWithContext(stack_trace_, MAX_STACK_DEPTH, /* skip_count = */ 1, context, + absl::GetStackTraceWithContext(stack_trace_, MaxStackDepth, /* skip_count = */ 1, context, /* min_dropped_frames = */ nullptr); } @@ -82,8 +82,8 @@ class BackwardsTrace : Logger::Loggable { } private: - static constexpr int MAX_STACK_DEPTH = 64; - void* stack_trace_[MAX_STACK_DEPTH]; - int stack_depth_; + static constexpr int MaxStackDepth = 64; + void* stack_trace_[MaxStackDepth]; + int stack_depth_{0}; }; } // namespace Envoy From cce16c0950f98c86e6ea8161bba7a8ca92583901 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Mon, 28 Jan 2019 10:14:58 -0500 Subject: [PATCH 3/8] Include addresses even if resolved, update README. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- bazel/README.md | 4 +++- source/server/backtrace.h | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/bazel/README.md b/bazel/README.md index 78cbf44abbadb..10cdd0f182fe0 100644 --- a/bazel/README.md +++ b/bazel/README.md @@ -187,7 +187,9 @@ Envoy can produce backtraces on demand and from assertions and other fatal actions like segfaults. Where supported, stack traces will contain resolved symbols, though not include line numbers. On systems where absl::Symbolization is not supported, the stack traces written in the log or to stderr contain addresses rather -than resolved symbols. +than resolved symbols. If the symbols were resolved, the address is also included at +the end of the line. It can be used with a debugging tool like `addr2line` to +get a precise line number if the required debugging info is available. You will need to use either a `dbg` build type or the `opt` build type to get symbol information in the binaries. diff --git a/source/server/backtrace.h b/source/server/backtrace.h index 67b0afe20fc52..8887876d90f16 100644 --- a/source/server/backtrace.h +++ b/source/server/backtrace.h @@ -70,7 +70,7 @@ class BackwardsTrace : Logger::Loggable { char out[1024]; const bool success = absl::Symbolize(stack_trace_[i], out, sizeof(out)); if (success) { - ENVOY_LOG(critical, "#{}: {}", i, out); + ENVOY_LOG(critical, "#{}: {} [{}]", i, out, stack_trace_[i]); } else { ENVOY_LOG(critical, "#{}: {}", i, stack_trace_[i]); } From 08fb3202bcbed531a158260efe9f3e904dd3fbd9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Tue, 29 Jan 2019 13:01:25 -0500 Subject: [PATCH 4/8] Modify stack_decode.py to work again. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- source/server/backtrace.h | 5 +-- tools/stack_decode.py | 69 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 72 insertions(+), 2 deletions(-) create mode 100755 tools/stack_decode.py diff --git a/source/server/backtrace.h b/source/server/backtrace.h index 8887876d90f16..e1e3f02ecd3b9 100644 --- a/source/server/backtrace.h +++ b/source/server/backtrace.h @@ -64,7 +64,8 @@ class BackwardsTrace : Logger::Loggable { * Log the stack trace. */ void logTrace() { - ENVOY_LOG(critical, "Backtrace:"); + ENVOY_LOG(critical, + "Backtrace (use tools/stack_decode.py to get line numbers):"); for (int i = 0; i < stack_depth_; ++i) { char out[1024]; @@ -72,7 +73,7 @@ class BackwardsTrace : Logger::Loggable { if (success) { ENVOY_LOG(critical, "#{}: {} [{}]", i, out, stack_trace_[i]); } else { - ENVOY_LOG(critical, "#{}: {}", i, stack_trace_[i]); + ENVOY_LOG(critical, "#{}: [{}]", i, stack_trace_[i]); } } } diff --git a/tools/stack_decode.py b/tools/stack_decode.py new file mode 100755 index 0000000000000..d3ddb603fbd15 --- /dev/null +++ b/tools/stack_decode.py @@ -0,0 +1,69 @@ +#!/usr/bin/env python + +# Call addr2line as needed to resolve addresses in a stack trace. The addresses +# will be replaced if they can be resolved into file and line numbers. The +# executable must include debugging information to get file and line numbers. +# +# Two ways to call: +# 1) Execute binary as a subprocess: stack_decode.py executable_file [args] +# 2) Read log data from stdin: stack_decode.py -s executable_file +# +# In each case this script will add file and line information to any backtrace log +# lines found and echo back all non-Backtrace lines untouched. + +import collections +import re +import subprocess +import sys + +# Process the log output looking for stacktrace snippets, for each line found to +# contain backtrace output extract the address and call add2line to get the file +# and line information. Output appended to end of original backtrace line. Output +# any nonmatching lines unmodified. End when EOF received. +def decode_stacktrace_log(object_file, input_source): + traces = {} + # Match something like [backtrace] + # bazel-out/local-dbg/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:84] + backtrace_marker = "\[backtrace\] [^\s]+" + stackaddr_re = re.compile("%s #\d+: .* \[(0x[0-9a-fA-F]+)\]$" % backtrace_marker) + + try: + while True: + line = input_source.readline() + if line == "": + return # EOF + stackaddr_match = stackaddr_re.search(line) + if stackaddr_match: + address = stackaddr_match.groups()[0] + file_and_line_number = run_addr2line(object_file, address) + sys.stdout.write("%s %s" % (line.strip(), file_and_line_number)) + continue + else: + # Pass through print all other log lines: + sys.stdout.write(line) + except KeyboardInterrupt: + return + + +# Execute addr2line with a particular object file and input string of addresses +# to resolve, one per line. +# +# Returns list of result lines +def run_addr2line(obj_file, addr_to_resolve): + addr2line = subprocess.Popen(["addr2line", "-Cpie", obj_file, addr_to_resolve], + stdout=subprocess.PIPE) + output_stdout, _ = addr2line.communicate() + return output_stdout + +if __name__ == "__main__": + if len(sys.argv) > 2 and sys.argv[1] == '-s': + decode_stacktrace_log(sys.argv[2], sys.stdin) + elif len(sys.argv) > 1: + rununder = subprocess.Popen(sys.argv[1:], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) + decode_stacktrace_log(sys.argv[1], rununder.stdout) + rununder.wait() + sys.exit(rununder.returncode) # Pass back test pass/fail result + else: + print "Usage (execute subprocess): stack_decode.py executable_file [additional args]" + print "Usage (read from stdin): stack_decode.py -s executable_file" + sys.exit(0) From 58139d575036f92aa01e0868f8b963cc3cf0fb6a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Tue, 29 Jan 2019 13:17:33 -0500 Subject: [PATCH 5/8] Re-fix-format. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- source/server/backtrace.h | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/source/server/backtrace.h b/source/server/backtrace.h index e1e3f02ecd3b9..aea8cf1013137 100644 --- a/source/server/backtrace.h +++ b/source/server/backtrace.h @@ -64,8 +64,7 @@ class BackwardsTrace : Logger::Loggable { * Log the stack trace. */ void logTrace() { - ENVOY_LOG(critical, - "Backtrace (use tools/stack_decode.py to get line numbers):"); + ENVOY_LOG(critical, "Backtrace (use tools/stack_decode.py to get line numbers):"); for (int i = 0; i < stack_depth_; ++i) { char out[1024]; From 2887f00b092572aaf9e926521d47a6111ad644b2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Tue, 29 Jan 2019 13:39:23 -0500 Subject: [PATCH 6/8] Fix python format with Docker container. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- tools/stack_decode.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tools/stack_decode.py b/tools/stack_decode.py index d3ddb603fbd15..6eba6fe1e0379 100755 --- a/tools/stack_decode.py +++ b/tools/stack_decode.py @@ -16,6 +16,7 @@ import subprocess import sys + # Process the log output looking for stacktrace snippets, for each line found to # contain backtrace output extract the address and call add2line to get the file # and line information. Output appended to end of original backtrace line. Output @@ -55,6 +56,7 @@ def run_addr2line(obj_file, addr_to_resolve): output_stdout, _ = addr2line.communicate() return output_stdout + if __name__ == "__main__": if len(sys.argv) > 2 and sys.argv[1] == '-s': decode_stacktrace_log(sys.argv[2], sys.stdin) From f3a928e0c843e95bfc651fd7301d36ba195c60cd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Wed, 30 Jan 2019 09:50:07 -0500 Subject: [PATCH 7/8] Trim /proc/cwd stuff, update docs. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- bazel/README.md | 25 +++++++++++++++++++++---- tools/stack_decode.py | 20 ++++++++++++++++++++ 2 files changed, 41 insertions(+), 4 deletions(-) diff --git a/bazel/README.md b/bazel/README.md index 10cdd0f182fe0..8d4584077b47a 100644 --- a/bazel/README.md +++ b/bazel/README.md @@ -188,11 +188,28 @@ actions like segfaults. Where supported, stack traces will contain resolved symbols, though not include line numbers. On systems where absl::Symbolization is not supported, the stack traces written in the log or to stderr contain addresses rather than resolved symbols. If the symbols were resolved, the address is also included at -the end of the line. It can be used with a debugging tool like `addr2line` to -get a precise line number if the required debugging info is available. +the end of the line. -You will need to use either a `dbg` build type or the `opt` build type to get symbol -information in the binaries. +The `tools/stack_decode.py` script exists to process the output and do additional symbol +resolution including file names and line numbers. It requires the `addr2line` program be +installed and in your path. Any log lines not relevant to the backtrace capability are +passed through the script unchanged (it acts like a filter). File and line information +is appended to the stack trace lines. + +The script runs in one of two modes. To process log input from stdin, pass `-s` as the first +argument, followed by the executable file path. You can postprocess a log or pipe the output +of an Envoy process. If you do not specify the `-s` argument it runs the arguments as a child +process. This enables you to run a test with backtrace post processing. Bazel sandboxing must +be disabled by specifying standalone execution. Example command line: + +``` +bazel test -c dbg //test/server:backtrace_test +--run_under=`pwd`/tools/stack_decode.py --strategy=TestRunner=standalone +--cache_test_results=no --test_output=all +``` + +You will need to use either a `dbg` build type or the `opt` build type to get file and line +symbol information in the binaries. By default main.cc will install signal handlers to print backtraces at the location where a fatal signal occurred. The signal handler will re-raise the diff --git a/tools/stack_decode.py b/tools/stack_decode.py index 6eba6fe1e0379..ece49bee98c26 100755 --- a/tools/stack_decode.py +++ b/tools/stack_decode.py @@ -37,6 +37,7 @@ def decode_stacktrace_log(object_file, input_source): if stackaddr_match: address = stackaddr_match.groups()[0] file_and_line_number = run_addr2line(object_file, address) + file_and_line_number = trim_proc_cwd(file_and_line_number) sys.stdout.write("%s %s" % (line.strip(), file_and_line_number)) continue else: @@ -57,6 +58,25 @@ def run_addr2line(obj_file, addr_to_resolve): return output_stdout +# Because of how bazel compiles, addr2line reports file names that begin with +# "/proc/self/cwd/" and sometimes even "/proc/self/cwd/./". This isn't particularly +# useful information, so trim it out and make a perfectly useful relative path. +def trim_proc_cwd(file_and_line_number): + # Try the longer trim first, it will leave the string untouched if it doesn't + # match. + file_and_line_number = trim_from_start(file_and_line_number, "/proc/self/cwd/./") + file_and_line_number = trim_from_start(file_and_line_number, "/proc/self/cwd/") + return file_and_line_number + + +def trim_from_start(string, trim): + if string.startswith(trim): + return string[len(trim):] + else: + + return string + + if __name__ == "__main__": if len(sys.argv) > 2 and sys.argv[1] == '-s': decode_stacktrace_log(sys.argv[2], sys.stdin) From 706107ae81850723ef9fac881b176b2304fd1dd5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dan=20No=C3=A9?= Date: Thu, 31 Jan 2019 11:30:51 -0500 Subject: [PATCH 8/8] Python nits and doc improvements. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Dan Noé --- bazel/README.md | 9 ++++++++- tools/stack_decode.py | 23 +++++------------------ 2 files changed, 13 insertions(+), 19 deletions(-) diff --git a/bazel/README.md b/bazel/README.md index 8d4584077b47a..52a8ae82b8865 100644 --- a/bazel/README.md +++ b/bazel/README.md @@ -200,7 +200,8 @@ The script runs in one of two modes. To process log input from stdin, pass `-s` argument, followed by the executable file path. You can postprocess a log or pipe the output of an Envoy process. If you do not specify the `-s` argument it runs the arguments as a child process. This enables you to run a test with backtrace post processing. Bazel sandboxing must -be disabled by specifying standalone execution. Example command line: +be disabled by specifying standalone execution. Example command line with +`run_under`: ``` bazel test -c dbg //test/server:backtrace_test @@ -208,6 +209,12 @@ bazel test -c dbg //test/server:backtrace_test --cache_test_results=no --test_output=all ``` +Example using input on stdin: + +``` +bazel test -c dbg //test/server:backtrace_test --cache_test_results=no --test_output=streamed |& tools/stack_decode.py -s bazel-bin/test/server/backtrace_test +``` + You will need to use either a `dbg` build type or the `opt` build type to get file and line symbol information in the binaries. diff --git a/tools/stack_decode.py b/tools/stack_decode.py index ece49bee98c26..eeb4143fc471e 100755 --- a/tools/stack_decode.py +++ b/tools/stack_decode.py @@ -52,34 +52,21 @@ def decode_stacktrace_log(object_file, input_source): # # Returns list of result lines def run_addr2line(obj_file, addr_to_resolve): - addr2line = subprocess.Popen(["addr2line", "-Cpie", obj_file, addr_to_resolve], - stdout=subprocess.PIPE) - output_stdout, _ = addr2line.communicate() - return output_stdout + return subprocess.check_output(["addr2line", "-Cpie", obj_file, addr_to_resolve]) # Because of how bazel compiles, addr2line reports file names that begin with # "/proc/self/cwd/" and sometimes even "/proc/self/cwd/./". This isn't particularly # useful information, so trim it out and make a perfectly useful relative path. def trim_proc_cwd(file_and_line_number): - # Try the longer trim first, it will leave the string untouched if it doesn't - # match. - file_and_line_number = trim_from_start(file_and_line_number, "/proc/self/cwd/./") - file_and_line_number = trim_from_start(file_and_line_number, "/proc/self/cwd/") - return file_and_line_number - - -def trim_from_start(string, trim): - if string.startswith(trim): - return string[len(trim):] - else: - - return string + trim_regex = r'/proc/self/cwd/(\./)?' + return re.sub(trim_regex, '', file_and_line_number) if __name__ == "__main__": if len(sys.argv) > 2 and sys.argv[1] == '-s': decode_stacktrace_log(sys.argv[2], sys.stdin) + sys.exit(0) elif len(sys.argv) > 1: rununder = subprocess.Popen(sys.argv[1:], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) decode_stacktrace_log(sys.argv[1], rununder.stdout) @@ -88,4 +75,4 @@ def trim_from_start(string, trim): else: print "Usage (execute subprocess): stack_decode.py executable_file [additional args]" print "Usage (read from stdin): stack_decode.py -s executable_file" - sys.exit(0) + sys.exit(1)