make debug() output more useful

This change does several things. First, and most important, it allows
dumping the "n" most recent stack frames on each debug() call. Second,
it demangles the C++ symbols. Third, it prepends each debug() message
with the debug level.

Unrelated to the above I've replaced all `assert(!is_forked_child());`
statements with `ASSERT_IS_NOT_FORKED_CHILD()` for consistency.

7 files changed, 114 insertions, 44 deletions

diff --git a/configure.ac b/configure.ac
index 3301b5bf..c97b8c51 100644
--- a/configure.ac
+++ b/configure.ac
@@ -362,6 +362,7 @@ AC_SEARCH_LIBS( pthread_create, pthread, , [AC_MSG_ERROR([Cannot find the pthrea
 AC_SEARCH_LIBS( setupterm, [ncurses tinfo curses], , [AC_MSG_ERROR([Could not find a curses implementation, needed to build fish. If this is Linux, try running 'sudo apt-get install libncurses5-dev' or 'sudo yum install ncurses-devel'])] )
 AC_SEARCH_LIBS( [nan], [m], [AC_DEFINE( [HAVE_NAN], [1], [Define to 1 if you have the nan function])] )
 AC_SEARCH_LIBS( [backtrace_symbols_fd], [execinfo] )
+AC_SEARCH_LIBS( [dladdr], [dl] )
 
 if test x$local_gettext != xno; then
   AC_SEARCH_LIBS( gettext, intl,,)
diff --git a/doc_src/fish.txt b/doc_src/fish.txt
index bf9c3eb1..eb4d24ba 100644
--- a/doc_src/fish.txt
+++ b/doc_src/fish.txt
@@ -25,4 +25,6 @@ The following options are available:
 
 - `-v` or `--version` display version and exit
 
+- `-D` or `--debug-stack-frames=DEBUG_LEVEL` specify how many stack frames to display when debug messages are written. The default is zero. A value of 3 or 4 is usually sufficient to gain insight into how a given debug call was reached but you can specify a value up to 128.
+
 The fish exit status is generally the exit status of the last foreground command. If fish is exiting because of a parse error, the exit status is 127.
diff --git a/src/common.cpp b/src/common.cpp
index 834f7b8b..aa27c537 100644
--- a/src/common.cpp
+++ b/src/common.cpp
@@ -2,6 +2,8 @@
 #include "config.h"
 
 #include <assert.h>
+#include <cxxabi.h>
+#include <dlfcn.h>
 #include <errno.h>
 #include <limits.h>
 #include <locale.h>
@@ -49,12 +51,16 @@ static bool thread_assertions_configured_for_testing = false;
 
 wchar_t ellipsis_char;
 wchar_t omitted_newline_char;
-
 bool g_profiling_active = false;
-
 const wchar_t *program_name;
+int debug_level = 1;         // default maximum debug output level (errors and warnings)
+int debug_stack_frames = 0;  // default number of stack frames to show on debug() calls
+
+/// This allows us to notice when we've forked.
+static pid_t initial_pid = 0;
 
-int debug_level = 1;
+/// Be able to restore the term's foreground process group.
+static pid_t initial_foreground_process_group = -1;
 
 /// This struct maintains the current state of the terminal size. It is updated on demand after
 /// receiving a SIGWINCH. Do not touch this struct directly, it's managed with a rwlock. Use
@@ -65,18 +71,53 @@ static rwlock_t termsize_rwlock;
 
 static char *wcs2str_internal(const wchar_t *in, char *out);
 
-void show_stackframe() {
+// This function produces a stack backtrace with demangled function & method names. It is based on
+// https://gist.github.com/fmela/591333 but adapted to the style of the fish project.
+static const wcstring_list_t __attribute__((noinline))
+demangled_backtrace(int max_frames, int skip_levels) {
+    void *callstack[128];
+    const int n_max_frames = sizeof(callstack) / sizeof(callstack[0]);
+    int n_frames = backtrace(callstack, n_max_frames);
+    char **symbols = backtrace_symbols(callstack, n_frames);
+    wchar_t text[1024];
+    std::vector<wcstring> backtrace_text;
+
+    if (skip_levels + max_frames < n_frames) n_frames = skip_levels + max_frames;
+
+    for (int i = skip_levels; i < n_frames; i++) {
+        Dl_info info;
+        if (dladdr(callstack[i], &info) && info.dli_sname) {
+            char *demangled = NULL;
+            int status = -1;
+            if (info.dli_sname[0] == '_')
+                demangled = abi::__cxa_demangle(info.dli_sname, NULL, 0, &status);
+            swprintf(text, sizeof(text) / sizeof(wchar_t), L"%-3d %s + %td", i - skip_levels,
+                     status == 0 ? demangled : info.dli_sname == 0 ? symbols[i] : info.dli_sname,
+                     (char *)callstack[i] - (char *)info.dli_saddr);
+            free(demangled);
+        } else {
+            swprintf(text, sizeof(text) / sizeof(wchar_t), L"%-3d %s", i - skip_levels, symbols[i]);
+        }
+        backtrace_text.push_back(text);
+    }
+    free(symbols);
+    return backtrace_text;
+}
+
+static void debug_shared(const wchar_t msg_level, const wcstring &msg);
+void __attribute__((noinline)) show_stackframe(const wchar_t msg_level, int frame_count,
+                                               int skip_levels) {
     ASSERT_IS_NOT_FORKED_CHILD();
 
     // Hack to avoid showing backtraces in the tester.
     if (program_name && !wcscmp(program_name, L"(ignore)")) return;
 
-    void *trace[32];
-    int trace_size = 0;
-
-    trace_size = backtrace(trace, 32);
-    debug(0, L"Backtrace:");
-    backtrace_symbols_fd(trace, trace_size, STDERR_FILENO);
+    if (frame_count < 1) frame_count = 999;
+    debug_shared(msg_level, L"Backtrace:");
+    std::vector<wcstring> bt = demangled_backtrace(frame_count, skip_levels + 2);
+    for (int i = 0; i < bt.size(); i++) {
+        debug_shared(msg_level, bt[i]);
+    }
 }
 
 int fgetws2(wcstring *s, FILE *f) {
@@ -493,23 +534,34 @@ static bool should_debug(int level) {
     return true;
 }
 
-static void debug_shared(const wcstring &msg) {
-    const wcstring sb = wcstring(program_name) + L": " + msg;
-    fwprintf(stderr, L"%ls", reformat_for_screen(sb).c_str());
+static void debug_shared(const wchar_t level, const wcstring &msg) {
+    pid_t current_pid = getpid();
+
+    if (current_pid == initial_pid) {
+        fwprintf(stderr, L"<%lc> %ls: %ls\n", (unsigned long)level, program_name, msg.c_str());
+    } else {
+        fwprintf(stderr, L"<%lc> %ls: %d: %ls\n", (unsigned long)level, program_name, current_pid,
+                 msg.c_str());
+    }
 }
 
-void debug(int level, const wchar_t *msg, ...) {
+static wchar_t level_char[] = {L'E', L'W', L'2', L'3', L'4', L'5'};
+void __attribute__((noinline)) debug(int level, const wchar_t *msg, ...) {
     if (!should_debug(level)) return;
     int errno_old = errno;
     va_list va;
     va_start(va, msg);
     wcstring local_msg = vformat_string(msg, va);
     va_end(va);
-    debug_shared(local_msg);
+    const wchar_t msg_level = level <= 5 ? level_char[level] : L'9';
+    debug_shared(msg_level, local_msg);
+    if (debug_stack_frames > 0) {
+        show_stackframe(msg_level, debug_stack_frames, 1);
+    }
     errno = errno_old;
 }
 
-void debug(int level, const char *msg, ...) {
+void __attribute__((noinline)) debug(int level, const char *msg, ...) {
     if (!should_debug(level)) return;
     int errno_old = errno;
     char local_msg[512];
@@ -517,7 +569,11 @@ void debug(int level, const char *msg, ...) {
     va_start(va, msg);
     vsnprintf(local_msg, sizeof local_msg, msg, va);
     va_end(va);
-    debug_shared(str2wcstring(local_msg));
+    const wchar_t msg_level = level <= 5 ? level_char[level] : L'9';
+    debug_shared(msg_level, str2wcstring(local_msg));
+    if (debug_stack_frames > 0) {
+        show_stackframe(msg_level, debug_stack_frames, 1);
+    }
     errno = errno_old;
 }
 
@@ -1470,7 +1526,7 @@ int create_directory(const wcstring &d) {
 }
 
 __attribute__((noinline)) void bugreport() {
-    debug(1, _(L"This is a bug. Break on bugreport to debug."
+    debug(1, _(L"This is a bug. Break on bugreport to debug. "
                L"If you can reproduce it, please send a bug report to %s."),
           PACKAGE_BUGREPORT);
 }
@@ -1630,12 +1686,6 @@ void configure_thread_assertions_for_testing(void) {
     thread_assertions_configured_for_testing = true;
 }
 
-/// Notice when we've forked.
-static pid_t initial_pid = 0;
-
-/// Be able to restore the term's foreground process group.
-static pid_t initial_foreground_process_group = -1;
-
 bool is_forked_child(void) {
     // Just bail if nobody's called setup_fork_guards, e.g. some of our tools.
     if (!initial_pid) return false;
@@ -1712,14 +1762,14 @@ void assert_is_locked(void *vmutex, const char *who, const char *caller) {
 
 void scoped_lock::lock(void) {
     assert(!locked);
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_mutex_lock(lock_obj));
     locked = true;
 }
 
 void scoped_lock::unlock(void) {
     assert(locked);
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_mutex_unlock(lock_obj));
     locked = false;
 }
@@ -1736,35 +1786,35 @@ scoped_lock::~scoped_lock() {
 
 void scoped_rwlock::lock(void) {
     assert(!(locked || locked_shared));
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_rdlock(rwlock_obj));
     locked = true;
 }
 
 void scoped_rwlock::unlock(void) {
     assert(locked);
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_unlock(rwlock_obj));
     locked = false;
 }
 
 void scoped_rwlock::lock_shared(void) {
     assert(!(locked || locked_shared));
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_wrlock(rwlock_obj));
     locked_shared = true;
 }
 
 void scoped_rwlock::unlock_shared(void) {
     assert(locked_shared);
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_unlock(rwlock_obj));
     locked_shared = false;
 }
 
 void scoped_rwlock::upgrade(void) {
     assert(locked_shared);
-    assert(!is_forked_child());
+    ASSERT_IS_NOT_FORKED_CHILD();
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_unlock(rwlock_obj));
     locked = false;
     VOMIT_ON_FAILURE_NO_ERRNO(pthread_rwlock_wrlock(rwlock_obj));
diff --git a/src/common.h b/src/common.h
index 3d1a771f..ea0805f0 100644
--- a/src/common.h
+++ b/src/common.h
@@ -175,6 +175,9 @@ extern wchar_t omitted_newline_char;
 /// it will not be printed.
 extern int debug_level;
 
+/// How many stack frames to show when a debug() call is made.
+extern int debug_stack_frames;
+
 /// Profiling flag. True if commands should be profiled.
 extern bool g_profiling_active;
 
@@ -192,7 +195,7 @@ void write_ignore(int fd, const void *buff, size_t count);
     if (!(arg)) {                                                                         \
         debug(0, "function %s called with null value for argument %s. ", __func__, #arg); \
         bugreport();                                                                      \
-        show_stackframe();                                                                \
+        show_stackframe(L'E');                                                            \
         return retval;                                                                    \
     }
 
@@ -200,7 +203,7 @@ void write_ignore(int fd, const void *buff, size_t count);
 #define FATAL_EXIT()                        \
     {                                       \
         char exit_read_buff;                \
-        show_stackframe();                  \
+        show_stackframe(L'E');              \
         read_ignore(0, &exit_read_buff, 1); \
         exit_without_destructors(1);        \
     }
@@ -219,7 +222,7 @@ void write_ignore(int fd, const void *buff, size_t count);
     if (signal_is_blocked()) {                                             \
         debug(0, "function %s called while blocking signals. ", __func__); \
         bugreport();                                                       \
-        show_stackframe();                                                 \
+        show_stackframe(L'E');                                             \
         return retval;                                                     \
     }
 
@@ -234,7 +237,7 @@ void write_ignore(int fd, const void *buff, size_t count);
 #define contains(str, ...) contains_internal(str, 0, __VA_ARGS__, NULL)
 
 /// Print a stack trace to stderr.
-void show_stackframe();
+void show_stackframe(const wchar_t msg_level, int frame_count = -1, int skip_levels = 0);
 
 /// Read a line from the stream f into the string. Returns the number of bytes read or -1 on
 /// failure.
@@ -485,8 +488,6 @@ class null_terminated_array_t {
 void convert_wide_array_to_narrow(const null_terminated_array_t<wchar_t> &arr,
                                   null_terminated_array_t<char> *output);
 
-bool is_forked_child();
-
 class mutex_lock_t {
    public:
     pthread_mutex_t mutex;
@@ -668,8 +669,8 @@ ssize_t read_loop(int fd, void *buff, size_t count);
 ///
 /// will print the string 'fish: Pi = 3.141', given that debug_level is 1 or higher, and that
 /// program_name is 'fish'.
-void debug(int level, const char *msg, ...);
-void debug(int level, const wchar_t *msg, ...);
+void __attribute__((noinline)) debug(int level, const char *msg, ...);
+void __attribute__((noinline)) debug(int level, const wchar_t *msg, ...);
 
 /// Replace special characters with backslash escape sequences. Newline is replaced with \n, etc.
 ///
diff --git a/src/exec.cpp b/src/exec.cpp
index 63f2cb77..afd09f6a 100644
--- a/src/exec.cpp
+++ b/src/exec.cpp
@@ -948,7 +948,7 @@ void exec_job(parser_t &parser, job_t *j) {
                             bool builtin_io_done = do_builtin_io(outbuff.data(), outbuff.size(),
                                                                  errbuff.data(), errbuff.size());
                             if (!builtin_io_done && errno != EPIPE) {
-                                show_stackframe();
+                                show_stackframe(L'E');
                             }
                             fork_was_skipped = true;
                         }
diff --git a/src/fish.cpp b/src/fish.cpp
index d8192c86..c4158dde 100644
--- a/src/fish.cpp
+++ b/src/fish.cpp
@@ -309,11 +309,12 @@ static int read_init(const struct config_paths_t &paths) {
     return 1;
 }
 
-/// Parse the argument list, return the index of the first non-switch arguments.
+/// Parse the argument list, return the index of the first non-flag arguments.
 static int fish_parse_opt(int argc, char **argv, std::vector<std::string> *cmds) {
-    const char *short_opts = "+hilnvc:p:d:";
+    const char *short_opts = "+hilnvc:p:d:D:";
     const struct option long_opts[] = {{"command", required_argument, NULL, 'c'},
                                        {"debug-level", required_argument, NULL, 'd'},
+                                       {"debug-stack-frames", required_argument, NULL, 'D'},
                                        {"interactive", no_argument, NULL, 'i'},
                                        {"login", no_argument, NULL, 'l'},
                                        {"no-execute", no_argument, NULL, 'n'},
@@ -343,7 +344,7 @@ static int fish_parse_opt(int argc, char **argv, std::vector<std::string> *cmds)
                 if (tmp >= 0 && tmp <= 10 && !*end && !errno) {
                     debug_level = (int)tmp;
                 } else {
-                    fwprintf(stderr, _(L"Invalid value '%s' for debug level switch"), optarg);
+                    fwprintf(stderr, _(L"Invalid value '%s' for debug-level flag"), optarg);
                     exit(1);
                 }
                 break;
@@ -373,6 +374,21 @@ static int fish_parse_opt(int argc, char **argv, std::vector<std::string> *cmds)
                 fwprintf(stdout, _(L"%s, version %s\n"), PACKAGE_NAME, get_fish_version());
                 exit(0);
             }
+            case 'D': {
+                char *end;
+                long tmp;
+
+                errno = 0;
+                tmp = strtol(optarg, &end, 10);
+
+                if (tmp > 0 && tmp <= 128 && !*end && !errno) {
+                    debug_stack_frames = (int)tmp;
+                } else {
+                    fwprintf(stderr, _(L"Invalid value '%s' for debug-stack-frames flag"), optarg);
+                    exit(1);
+                }
+                break;
+            }
             default: {
                 // We assume getopt_long() has already emitted a diagnostic msg.
                 exit(1);
diff --git a/tests/status.err b/tests/status.err
index 91645c95..b04178e4 100644
--- a/tests/status.err
+++ b/tests/status.err
@@ -1,2 +1,2 @@
-fish: An error occurred while redirecting file '/'
+<W> fish: An error occurred while redirecting file '/'
 open: Is a directory