Print backtraces on FATAL log messages in debug mode.

This provides basic support for looking up backtrace information on GNU libc systems and in Windows.  The code is only enabled for FATAL log messages in debug mode.  In a release build, it is unlikely that symbols will be available making the backtrace less useful.

Review URL: http://codereview.chromium.org/62140

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@14391 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 314 insertions, 17 deletions

diff --git a/base/base.gyp b/base/base.gyp
index 977b9d8..58601ae 100644
--- a/base/base.gyp
+++ b/base/base.gyp
@@ -549,6 +549,7 @@
         'command_line_unittest.cc',
         'condition_variable_unittest.cc',
         'data_pack_unittest.cc',
+        'debug_util_unittest.cc',
         'directory_watcher_unittest.cc',
         'field_trial_unittest.cc',
         'file_path_unittest.cc',
diff --git a/base/debug_util.h b/base/debug_util.h
index de49c43..3ca199c 100644
--- a/base/debug_util.h
+++ b/base/debug_util.h
@@ -1,4 +1,4 @@
-// Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
+// Copyright (c) 2006-2009 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
@@ -9,10 +9,11 @@
 #ifndef BASE_DEBUG_UTIL_H_
 #define BASE_DEBUG_UTIL_H_
 
-#include "base/basictypes.h"
-
+#include <iostream>
 #include <vector>
 
+#include "base/basictypes.h"
+
 // A stacktrace can be helpful in debugging. For example, you can include a
 // stacktrace member in a object (probably around #ifndef NDEBUG) so that you
 // can later see where the given object was created from.
@@ -26,6 +27,9 @@ class StackTrace {
   // Print a backtrace to stderr
   void PrintBacktrace();
 
+  // Resolve backtrace to symbols and write to stream.
+  void OutputToStream(std::ostream* os);
+
  private:
   std::vector<void*> trace_;
 
diff --git a/base/debug_util_posix.cc b/base/debug_util_posix.cc
index 60e2ff5..ced59c8 100644
--- a/base/debug_util_posix.cc
+++ b/base/debug_util_posix.cc
@@ -1,10 +1,11 @@
-// Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
+// Copyright (c) 2006-2009 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "build/build_config.h"
 #include "base/debug_util.h"
 
+#include <errno.h>
 #include <execinfo.h>
 #include <fcntl.h>
 #include <stdio.h>
@@ -15,6 +16,7 @@
 
 #include "base/basictypes.h"
 #include "base/logging.h"
+#include "base/scoped_ptr.h"
 #include "base/string_piece.h"
 
 // static
@@ -109,15 +111,43 @@ void DebugUtil::BreakDebugger() {
 }
 
 StackTrace::StackTrace() {
-  static const int kMaxCallers = 256;
+  const int kMaxCallers = 256;
 
   void* callers[kMaxCallers];
   int count = backtrace(callers, kMaxCallers);
-  trace_.resize(count);
-  memcpy(&trace_[0], callers, sizeof(void*) * count);
+
+  // Though the backtrace API man page does not list any possible negative
+  // return values, we still still exclude them because they would break the
+  // memcpy code below.
+  if (count > 0) {
+    trace_.resize(count);
+    memcpy(&trace_[0], callers, sizeof(callers[0]) * count);
+  } else {
+    trace_.resize(0);
+  }
 }
 
 void StackTrace::PrintBacktrace() {
   fflush(stderr);
   backtrace_symbols_fd(&trace_[0], trace_.size(), STDERR_FILENO);
 }
+
+void StackTrace::OutputToStream(std::ostream* os) {
+  scoped_ptr_malloc<char*> trace_symbols(
+      backtrace_symbols(&trace_[0], trace_.size()));
+
+  // If we can't retrieve the symbols, print an error and just dump the raw
+  // addresses.
+  if (trace_symbols.get() == NULL) {
+    (*os) << "Unable get symbols for backtrace (" << strerror(errno)
+          << "). Dumping raw addresses in trace:\n";
+    for (size_t i = 0; i < trace_.size(); ++i) {
+      (*os) << "\t" << trace_[i] << "\n";
+    }
+  } else {
+    (*os) << "Backtrace:\n";
+    for (size_t i = 0; i < trace_.size(); ++i) {
+      (*os) << "\t" << trace_symbols.get()[i] << "\n";
+    }
+  }
+}
diff --git a/base/debug_util_unittest.cc b/base/debug_util_unittest.cc
new file mode 100644
index 0000000..2636e45
--- /dev/null
+++ b/base/debug_util_unittest.cc
@@ -0,0 +1,72 @@
+// Copyright (c) 2006-2009 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include <sstream>
+#include <string>
+
+#include "base/debug_util.h"
+#include "base/logging.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+TEST(StackTrace, OutputToStream) {
+  StackTrace trace;
+
+  // Dump the trace into a string.
+  std::ostringstream os;
+  trace.OutputToStream(&os);
+  std::string backtrace_message = os.str();
+
+  size_t frames_found = 0;
+  trace.Addresses(&frames_found);
+  if (frames_found == 0) {
+    LOG(ERROR) << "No stack frames found.  Skipping rest of test.";
+    return;
+  }
+
+  // Check if the output has symbol initialization warning.  If it does, fail.
+  if (backtrace_message.find("Dumping unresolved backtrace") != 
+      std::string::npos) {
+    LOG(ERROR) << "Unable to resolve symbols.  Skipping rest of test.";
+    return;
+  }
+
+#if defined(OS_MACOSX)
+
+  // Symbol resolution via the backtrace_symbol funciton does not work well
+  // in OsX.
+  // See this thread: 
+  //
+  //    http://lists.apple.com/archives/darwin-dev/2009/Mar/msg00111.html
+  //
+  // Just check instead that we find our way back to the "start" symbol
+  // which should be the first symbol in the trace.
+  //
+  // TODO(port): Find a more reliable way to resolve symbols.
+
+  // Expect to at least find main.
+  EXPECT_TRUE(backtrace_message.find("start") != std::string::npos)
+      << "Expected to find start in backtrace:\n"
+      << backtrace_message;
+
+#else  // defined(OS_MACOSX)
+
+  // Expect to at least find main.
+  EXPECT_TRUE(backtrace_message.find("main") != std::string::npos)
+      << "Expected to find main in backtrace:\n"
+      << backtrace_message;
+
+#if defined(OS_WIN)
+// MSVC doesn't allow the use of C99's __func__ within C++, so we fake it with
+// MSVC's __FUNCTION__ macro.
+#define __func__ __FUNCTION__
+#endif
+
+  // Expect to find this function as well.
+  // Note: This will fail if not linked with -rdynamic (aka -export_dynamic)
+  EXPECT_TRUE(backtrace_message.find(__func__) != std::string::npos)
+      << "Expected to find " << __func__ << " in backtrace:\n"
+      << backtrace_message;
+
+#endif  // define(OS_MACOSX)
+}
diff --git a/base/debug_util_win.cc b/base/debug_util_win.cc
index a41f1b3..5201283 100644
--- a/base/debug_util_win.cc
+++ b/base/debug_util_win.cc
@@ -1,12 +1,16 @@
-// Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
+// Copyright (c) 2006-2009 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include "base/debug_util.h"
+
 #include <windows.h>
+#include <dbghelp.h>
 
 #include "base/basictypes.h"
-#include "base/debug_util.h"
-#include "logging.h"
+#include "base/lock.h"
+#include "base/logging.h"
+#include "base/singleton.h"
 
 namespace {
 
@@ -62,6 +66,151 @@ bool StringReplace(const wchar_t* input, int value, wchar_t* output,
   return true;
 }
 
+// SymbolContext is a threadsafe singleton that wraps the DbgHelp Sym* family
+// of functions.  The Sym* family of functions may only be invoked by one
+// thread at a time.  SymbolContext code may access a symbol server over the
+// network while holding the lock for this singleton.  In the case of high
+// latency, this code will adversly affect performance.
+//
+// There is also a known issue where this backtrace code can interact
+// badly with breakpad if breakpad is invoked in a separate thread while
+// we are using the Sym* functions.  This is because breakpad does now
+// share a lock with this function.  See this related bug:
+//
+//   http://code.google.com/p/google-breakpad/issues/detail?id=311
+//
+// This is a very unlikely edge case, and the current solution is to
+// just ignore it.
+class SymbolContext {
+ public:
+  static SymbolContext* Get() {
+    // We use a leaky singleton because code may call this during process
+    // termination.
+    return
+      Singleton<SymbolContext, LeakySingletonTraits<SymbolContext> >::get();
+  }
+
+  // Initializes the symbols for the process if it hasn't been done yet.
+  // Subsequent calls will not reinitialize the symbol, but instead return
+  // the error code from the first call.
+  bool Init() {
+    AutoLock lock(lock_);
+    if (!initialized_) {
+      process_ = GetCurrentProcess();
+
+      // Defer symbol load until they're needed, use undecorated names, and
+      // get line numbers.
+      SymSetOptions(SYMOPT_DEFERRED_LOADS |
+                    SYMOPT_UNDNAME |
+                    SYMOPT_LOAD_LINES);
+      if (SymInitialize(process_, NULL, TRUE)) {
+        init_error_ = ERROR_SUCCESS;
+      } else {
+        init_error_ = GetLastError();
+      }
+    }
+
+    initialized_ = true;
+    return init_error_ == ERROR_SUCCESS;
+  }
+
+  // Returns the error code of a failed initialization.  This should only be
+  // called if Init() has been called.  We do not LOG(FATAL) here because
+  // this code is called might be triggered by a LOG(FATAL) itself.  Instead,
+  // we log an ERROR, and return ERROR_INVALID_DATA.
+  DWORD init_error() {
+    if (!initialized_) {
+      LOG(ERROR) << "Calling GetInitError() before Init() was called.  "
+                 << "Returning ERROR_INVALID_DATA.";
+      return ERROR_INVALID_DATA;
+    }
+
+    return init_error_;
+  }
+
+  // Returns the process this was initialized for.  This should only be
+  // called if Init() has been called.  We LOG(ERROR) in this situation.
+  // LOG(FATAL) is not used because this code is might be triggered 
+  // by a LOG(FATAL) itself.
+  HANDLE process() {
+    if (!initialized_) {
+      LOG(ERROR) << "Calling process() before Init() was called. "
+                 << "Returning NULL.";
+      return NULL;
+    }
+
+    return process_;
+  }
+
+  // For the given trace, attempts to resolve the symbols, and output a trace
+  // to the ostream os.  The format for each line of the backtrace is:
+  //
+  //    <tab>SymbolName[0xAddress+Offset] (FileName:LineNo)
+  // 
+  // This function should only be called if Init() has been called.  We do not
+  // LOG(FATAL) here because this code is called might be triggered by a
+  // LOG(FATAL) itself.
+  void OutputTraceToStream(const std::vector<void*>& trace, std::ostream* os) {
+    AutoLock lock(lock_);
+
+    for (size_t i = 0; (i < trace.size()) && os->good(); ++i) {
+      const int kMaxNameLength = 256;
+      DWORD_PTR frame = reinterpret_cast<DWORD_PTR>(trace[i]);
+
+      // Code adapted from MSDN example:
+      // http://msdn.microsoft.com/en-us/library/ms680578(VS.85).aspx
+      ULONG64 buffer[
+        (sizeof(SYMBOL_INFO) +
+          kMaxNameLength * sizeof(wchar_t) +
+          sizeof(ULONG64) - 1) /
+        sizeof(ULONG64)];
+
+      // Initialize symbol information retrieval structures.
+      DWORD64 sym_displacement = 0;
+      PSYMBOL_INFO symbol = reinterpret_cast<PSYMBOL_INFO>(&buffer[0]);
+      symbol->SizeOfStruct = sizeof(SYMBOL_INFO);
+      symbol->MaxNameLen = kMaxNameLength;
+      BOOL has_symbol = SymFromAddr(process(), frame,
+                                    &sym_displacement, symbol);
+
+      // Attempt to retrieve line number information.
+      DWORD line_displacement = 0;
+      IMAGEHLP_LINE64 line = {};
+      line.SizeOfStruct = sizeof(IMAGEHLP_LINE64);
+      BOOL has_line = SymGetLineFromAddr64(process(), frame,
+                                           &line_displacement, &line);
+
+      // Output the backtrace line.
+      (*os) << "\t";
+      if (has_symbol) {
+        (*os) << symbol->Name << " [0x" << trace[i] << "+"
+              << sym_displacement << "]";
+      } else {
+        // If there is no symbol informtion, add a spacer.
+        (*os) << "(No symbol) [0x" << trace[i] << "]";
+      }
+      if (has_line) {
+        (*os) << " (" << line.FileName << ":" << line.LineNumber << ")";
+      }
+      (*os) << "\n";
+    }
+  }
+
+  SymbolContext()
+    : initialized_(false),
+      process_(NULL),
+      init_error_(ERROR_SUCCESS) {
+  }
+
+ private:
+  Lock lock_;
+  bool initialized_;
+  HANDLE process_;
+  DWORD init_error_;
+
+  DISALLOW_COPY_AND_ASSIGN(SymbolContext);
+};
+
 }  // namespace
 
 // Note: Does not use the CRT.
@@ -102,10 +251,39 @@ void DebugUtil::BreakDebugger() {
   __debugbreak();
 }
 
-// TODO(port): not implemented on Windows
 StackTrace::StackTrace() {
+  // From http://msdn.microsoft.com/en-us/library/bb204633(VS.85).aspx,
+  // the sum of FramesToSkip and FramesToCapture must be less than 63,
+  // so set it to 62.
+  const int kMaxCallers = 62;
+
+  void* callers[kMaxCallers];
+  // TODO(ajwong): Migrate this to StackWalk64.
+  int count = CaptureStackBackTrace(0, kMaxCallers, callers, NULL);
+  if (count > 0) {
+    trace_.resize(count);
+    memcpy(&trace_[0], callers, sizeof(callers[0]) * count);
+  } else {
+    trace_.resize(0);
+  }
 }
 
-void PrintBacktrace() {
-  NOTIMPLEMENTED();
+void StackTrace::PrintBacktrace() {
+  OutputToStream(&std::cerr);
+}
+
+void StackTrace::OutputToStream(std::ostream* os) {
+  SymbolContext* context = SymbolContext::Get();
+
+  if (context->Init() != ERROR_SUCCESS) {
+    DWORD error = context->init_error();
+    (*os) << "Error initializing symbols (" << error
+          << ").  Dumping unresolved backtrace:\n";
+    for (size_t i = 0; (i < trace_.size()) && os->good(); ++i) {
+      (*os) << "\t" << trace_[i] << "\n";
+    }
+  } else {
+    (*os) << "Backtrace:\n";
+    context->OutputTraceToStream(trace_, os);
+  }
 }
diff --git a/base/logging.cc b/base/logging.cc
index 961ea6c..7b89020 100644
--- a/base/logging.cc
+++ b/base/logging.cc
@@ -1,4 +1,4 @@
-// Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
+// Copyright (c) 2006-2009 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
@@ -520,6 +520,13 @@ LogMessage::~LogMessage() {
     if (DebugUtil::BeingDebugged()) {
       DebugUtil::BreakDebugger();
     } else {
+#ifndef NDEBUG
+      // Dump a stack trace on a fatal.
+      StackTrace trace;
+      stream_ << "\n";  // Newline to separate from log message.
+      trace.OutputToStream(&stream_);
+#endif
+
       if (log_assert_handler) {
         // make a copy of the string for the handler out of paranoia
         log_assert_handler(std::string(stream_.str()));
@@ -554,7 +561,7 @@ void CloseLogFile() {
   log_file = NULL;
 }
 
-} // namespace logging
+}  // namespace logging
 
 std::ostream& operator<<(std::ostream& out, const wchar_t* wstr) {
   return out << base::SysWideToUTF8(std::wstring(wstr));
diff --git a/build/common.gypi b/build/common.gypi
index d464b1b..dccad5f 100644
--- a/build/common.gypi
+++ b/build/common.gypi
@@ -257,7 +257,10 @@
               '-O<(debug_optimize)',
               '-g',
             ],
-          },
+            'ldflags': [
+              '-rdynamic',  # Allows backtrace to resolve symbols.
+            ],
+	  },
           'Release': {
             'cflags': [
               '-O2',
@@ -382,10 +385,11 @@
               'ws2_32.lib',
               'usp10.lib',
               'psapi.lib',
+              'dbghelp.lib',
             ],
             'AdditionalLibraryDirectories':
               '<(DEPTH)/third_party/platformsdk_win2008_6_1/files/Lib',
-            'DelayLoadDLLs': 'dwmapi.dll,uxtheme.dll',
+            'DelayLoadDLLs': 'dbghelp.dll,dwmapi.dll,uxtheme.dll',
             'GenerateDebugInformation': 'true',
             'MapFileName': '$(OutDir)\\$(TargetName).map',
             'ImportLibrary': '$(OutDir)\\lib\\$(TargetName).lib',
diff --git a/chrome/app/chrome.dll.deps b/chrome/app/chrome.dll.deps
index afb5710..76e8b0d 100644
--- a/chrome/app/chrome.dll.deps
+++ b/chrome/app/chrome.dll.deps
@@ -27,6 +27,7 @@ delay_loaded = [
   'WS2_32.dll',
   'PSAPI.DLL',
   'dwmapi.dll',
+  'dbghelp.dll',
   'COMDLG32.dll',
   'urlmon.dll',
   'avcodec-52.dll',