Emit symbolizable backtraces on DCHECK/LOG(FATAL) under Fuchsia.

This adds code to query the process' debug symbol maps for offsets
and produces an externally symbolizable backtrace using that data.

R: thakis@chromium.org,wez@chromium.org
CC: jamesr@chromium.org
Bug: 706592
Change-Id: I7b3257ff154671b2eb1c90f7ab91947f55cfa873
Reviewed-on: https://chromium-review.googlesource.com/575290
Commit-Queue: Kevin Marshall <kmarshall@chromium.org>
Reviewed-by: Wez <wez@chromium.org>
Reviewed-by: Nico Weber <thakis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#491470}

base/debug/stack_trace_fuchsia.cc

@@ -4,14 +4,20 @@
 
 #include "base/debug/stack_trace.h"
 
+#include <link.h>
+#include <magenta/crashlogger.h>
 #include <magenta/process.h>
 #include <magenta/syscalls.h>
+#include <magenta/syscalls/definitions.h>
 #include <magenta/syscalls/port.h>
 #include <magenta/types.h>
+#include <stddef.h>
+#include <string.h>
 #include <threads.h>
 #include <unwind.h>
 
 #include <algorithm>
+#include <iomanip>
 #include <iostream>
 
 #include "base/logging.h"
@@ -21,6 +27,9 @@ namespace debug {
 
 namespace {
 
+const char kProcessNamePrefix[] = "app:";
+const size_t kProcessNamePrefixLen = arraysize(kProcessNamePrefix) - 1;
+
 struct BacktraceData {
   void** trace_array;
   size_t* count;
@@ -38,6 +47,110 @@ _Unwind_Reason_Code UnwindStore(struct _Unwind_Context* context,
   return _URC_NO_REASON;
 }
 
+// Stores and queries debugging symbol map info for the current process.
+class SymbolMap {
+ public:
+  struct Entry {
+    void* addr;
+    char name[MX_MAX_NAME_LEN + 1];
+  };
+
+  SymbolMap();
+  ~SymbolMap() = default;
+
+  // Gets the symbol map entry for |address|. Returns null if no entry could be
+  // found for the address, or if the symbol map could not be queried.
+  Entry* GetForAddress(void* address);
+
+ private:
+  static const size_t kMaxMapEntries = 64;
+
+  void Populate();
+
+  // Sorted in descending order by address, for lookup purposes.
+  Entry entries_[kMaxMapEntries];
+
+  size_t count_ = 0;
+  bool valid_ = false;
+
+  DISALLOW_COPY_AND_ASSIGN(SymbolMap);
+};
+
+SymbolMap::SymbolMap() {
+  Populate();
+}
+
+SymbolMap::Entry* SymbolMap::GetForAddress(void* address) {
+  if (!valid_) {
+    return nullptr;
+  }
+
+  // Working backwards in the address space, return the first map entry whose
+  // address comes before |address| (thereby enclosing it.)
+  for (size_t i = 0; i < count_; ++i) {
+    if (address >= entries_[i].addr) {
+      return &entries_[i];
+    }
+  }
+  return nullptr;
+}
+
+void SymbolMap::Populate() {
+  mx_handle_t process = mx_process_self();
+
+  // Get the process' name.
+  char app_name[MX_MAX_NAME_LEN + kProcessNamePrefixLen];
+  strcpy(app_name, kProcessNamePrefix);
+  auto status = mx_object_get_property(
+      process, MX_PROP_NAME, app_name + kProcessNamePrefixLen,
+      sizeof(app_name) - kProcessNamePrefixLen);
+  if (status != MX_OK) {
+    DPLOG(WARNING)
+        << "Couldn't get name, falling back to 'app' for program name: "
+        << status;
+    strlcpy(app_name, "app", sizeof(app_name));
+  }
+
+  // Retrieve the debug info struct.
+  constexpr size_t map_capacity = sizeof(entries_);
+  uintptr_t debug_addr;
+  status = mx_object_get_property(process, MX_PROP_PROCESS_DEBUG_ADDR,
+                                  &debug_addr, sizeof(debug_addr));
+  if (status != MX_OK) {
+    DPLOG(ERROR) << "Couldn't get symbol map for process: " << status;
+    return;
+  }
+  r_debug* debug_info = reinterpret_cast<r_debug*>(debug_addr);
+
+  // Get the link map from the debug info struct.
+  link_map* lmap = reinterpret_cast<link_map*>(debug_info->r_map);
+  if (!lmap) {
+    DPLOG(ERROR) << "Null link_map for process.";
+    return;
+  }
+
+  // Copy the contents of the link map linked list to |entries_|.
+  while (lmap != nullptr) {
+    if (count_ == map_capacity) {
+      break;
+    }
+    SymbolMap::Entry* next_entry = &entries_[count_];
+    count_++;
+
+    next_entry->addr = reinterpret_cast<void*>(lmap->l_addr);
+    char* name_to_use = lmap->l_name[0] ? lmap->l_name : app_name;
+    size_t name_len = strnlen(name_to_use, MX_MAX_NAME_LEN);
+    strncpy(next_entry->name, name_to_use, name_len + 1);
+    lmap = lmap->l_next;
+  }
+
+  std::sort(
+      &entries_[0], &entries_[count_ - 1],
+      [](const Entry& a, const Entry& b) -> bool { return a.addr >= b.addr; });
+
+  valid_ = true;
+}
+
 }  // namespace
 
 // static
@@ -60,12 +173,36 @@ void StackTrace::Print() const {
   OutputToStream(&std::cerr);
 }
 
+// Sample stack trace output:
+// #00 0x1527a058aa00 app:/system/base_unittests+0x18bda00
+// #01 0x1527a0254b5c app:/system/base_unittests+0x1587b5c
+// #02 0x15279f446ece app:/system/base_unittests+0x779ece
+// ...
+// #21 0x1527a05b51b4 app:/system/base_unittests+0x18e81b4
+// #22 0x54fdbf3593de libc.so+0x1c3de
+// #23 end
 void StackTrace::OutputToStream(std::ostream* os) const {
-  // TODO(fuchsia): Consider doing symbol resolution here. See
-  // https://crbug.com/706592.
-  for (size_t i = 0; (i < count_) && os->good(); ++i) {
-    (*os) << "\t" << trace_[i] << "\n";
+  SymbolMap map;
+
+  size_t i = 0;
+  for (; (i < count_) && os->good(); ++i) {
+    auto entry = map.GetForAddress(trace_[i]);
+    if (entry) {
+      size_t offset = reinterpret_cast<uintptr_t>(trace_[i]) -
+                      reinterpret_cast<uintptr_t>(entry->addr);
+      *os << "#" << std::setw(2) << std::setfill('0') << i << std::setw(0)
+          << " " << trace_[i] << " " << entry->name << "+0x" << std::hex
+          << offset << std::dec << std::setw(0) << "\n";
+    } else {
+      // Fallback if the DSO map isn't available.
+      // Logged PC values are absolute memory addresses, and the shared object
+      // name is not emitted.
+      *os << "#" << std::setw(2) << std::setfill('0') << i << std::setw(0)
+          << trace_[i] << "\n";
+    }
   }
+
+  (*os) << "#" << std::setw(2) << i << " end\n";
 }
 
 }  // namespace debug

build/fuchsia/test_runner.py

@@ -28,7 +28,11 @@ def RunAndCheck(dry_run, args):
   if dry_run:
     print 'Run:', args
   else:
-    subprocess.check_call(args)
+    try:
+      subprocess.check_call(args)
+      return 0
+    except subprocess.CalledProcessError as e:
+      return e.returncode
 
 
 def DumpFile(dry_run, name, description):
@@ -179,7 +183,7 @@ def SymbolizeEntry(entry):
   # that to align it properly after the frame index.
   addr2line_filtered = addr2line_output.strip().replace(
       '(inlined', ' ' * len(prefix) + '(inlined')
-  return '#%s: %s' % (prefix, addr2line_filtered)
+  return '%s%s' % (prefix, addr2line_filtered)
 
 
 def ParallelSymbolizeBacktrace(backtrace):
@@ -283,78 +287,90 @@ def main():
     # currently. See https://crbug.com/749242.
     bootserver_path = os.path.join(SDK_ROOT, 'tools', 'bootserver')
     bootserver_command = [bootserver_path, '-1', kernel_path, bootfs]
-    RunAndCheck(args.dry_run, bootserver_command)
+    return RunAndCheck(args.dry_run, bootserver_command)
+
+  qemu_path = os.path.join(SDK_ROOT, 'qemu', 'bin', 'qemu-system-x86_64')
+  qemu_command = [qemu_path,
+      '-m', '2048',
+      '-nographic',
+      '-net', 'none',
+      '-smp', '4',
+      '-machine', 'q35',
+      '-kernel', kernel_path,
+      '-initrd', bootfs,
+
+      # Use stdio for the guest OS only; don't attach the QEMU interactive
+      # monitor.
+      '-serial', 'stdio',
+      '-monitor', 'none',
+
+      # TERM=dumb tells the guest OS to not emit ANSI commands that trigger
+      # noisy ANSI spew from the user's terminal emulator.
+      '-append', 'TERM=dumb kernel.halt_on_panic=true']
+
+  if int(os.environ.get('CHROME_HEADLESS', 0)) == 0:
+    qemu_command += ['-enable-kvm', '-cpu', 'host,migratable=no']
   else:
-    qemu_path = os.path.join(SDK_ROOT, 'qemu', 'bin', 'qemu-system-x86_64')
-
-    qemu_command = [qemu_path,
-        '-m', '2048',
-        '-nographic',
-        '-net', 'none',
-        '-smp', '4',
-        '-machine', 'q35',
-        '-kernel', kernel_path,
-        '-initrd', bootfs,
-
-        # Use stdio for the guest OS only; don't attach the QEMU interactive
-        # monitor.
-        '-serial', 'stdio',
-        '-monitor', 'none',
-
-        # TERM=dumb tells the guest OS to not emit ANSI commands that trigger
-        # noisy ANSI spew from the user's terminal emulator.
-        '-append', 'TERM=dumb kernel.halt_on_panic=true']
-    if int(os.environ.get('CHROME_HEADLESS', 0)) == 0:
-      qemu_command += ['-enable-kvm', '-cpu', 'host,migratable=no']
+    qemu_command += ['-cpu', 'Haswell,+smap,-check']
+
+  if args.dry_run:
+    print 'Run:', qemu_command
+    return 0
+
+  # Set up backtrace-parsing regexps.
+  prefix = r'^.*> '
+  bt_end_re = re.compile(prefix + '(bt)?#(\d+):? end')
+  bt_with_offset_re = re.compile(
+      prefix + 'bt#(\d+): pc 0x[0-9a-f]+ sp (0x[0-9a-f]+) ' +
+               '\((\S+),(0x[0-9a-f]+)\)$')
+  in_process_re = re.compile(prefix +
+                             '#(\d+) 0x[0-9a-f]+ \S+\+(0x[0-9a-f]+)$')
+
+  # We pass a separate stdin stream to qemu. Sharing stdin across processes
+  # leads to flakiness due to the OS prematurely killing the stream and the
+  # Python script panicking and aborting.
+  # The precise root cause is still nebulous, but this fix works.
+  # See crbug.com/741194 .
+  qemu_popen = subprocess.Popen(
+      qemu_command, stdout=subprocess.PIPE, stdin=open(os.devnull))
+
+  # A buffer of backtrace entries awaiting symbolization, stored as tuples.
+  # Element #0: backtrace frame number (starting at 0).
+  # Element #1: path to executable code corresponding to the current frame.
+  # Element #2: memory offset within the executable.
+  bt_entries = []
+
+  success = False
+  while True:
+    line = qemu_popen.stdout.readline().strip()
+    if not line:
+      break
+    print line
+    if 'SUCCESS: all tests passed.' in line:
+      success = True
+    if bt_end_re.match(line):
+      if bt_entries:
+        print '----- start symbolized stack'
+        for processed in ParallelSymbolizeBacktrace(bt_entries):
+          print processed
+        print '----- end symbolized stack'
+      bt_entries = []
     else:
-      qemu_command += ['-cpu', 'Haswell,+smap,-check']
+      # Try to parse this as a Fuchsia system backtrace.
+      m = bt_with_offset_re.match(line)
+      if m:
+        bt_entries.append((m.group(1), args.test_name, m.group(4)))
+        continue
 
-    if args.dry_run:
-      print 'Run:', qemu_command
-    else:
-      prefix = r'^.*> '
-      bt_with_offset_re = re.compile(prefix +
-          'bt#(\d+): pc 0x[0-9a-f]+ sp (0x[0-9a-f]+) \((\S+),(0x[0-9a-f]+)\)$')
-      bt_end_re = re.compile(prefix + 'bt#(\d+): end')
-
-      # We pass a separate stdin stream to qemu. Sharing stdin across processes
-      # leads to flakiness due to the OS prematurely killing the stream and the
-      # Python script panicking and aborting.
-      # The precise root cause is still nebulous, but this fix works.
-      # See crbug.com/741194 .
-      qemu_popen = subprocess.Popen(
-          qemu_command, stdout=subprocess.PIPE, stdin=open(os.devnull))
-
-      # A buffer of backtrace entries awaiting symbolization, stored as tuples.
-      # Element #0: backtrace frame number (starting at 0).
-      # Element #1: path to executable code corresponding to the current frame.
-      # Element #2: memory offset within the executable.
-      bt_entries = []
+      # Try to parse the line as an in-process backtrace entry.
+      m = in_process_re.match(line)
+      if m:
+        bt_entries.append((m.group(1), args.test_name, m.group(2)))
+        continue
+
+  qemu_popen.wait()
 
-      success = False
-      while True:
-        line = qemu_popen.stdout.readline()
-        if not line:
-          break
-        print line,
-        if 'SUCCESS: all tests passed.' in line:
-          success = True
-        if bt_end_re.match(line.strip()):
-          if bt_entries:
-            print '----- start symbolized stack'
-            for processed in ParallelSymbolizeBacktrace(bt_entries):
-              print processed
-            print '----- end symbolized stack'
-          bt_entries = []
-        else:
-          m = bt_with_offset_re.match(line.strip())
-          if m:
-            bt_entries.append((m.group(1), args.test_name, m.group(4)))
-      qemu_popen.wait()
-
-      return 0 if success else 1
-
-  return 0
+  return 0 if success else 1
 
 
 if __name__ == '__main__':