Add backtrace support for error reporting
authorAlvaro Herrera <[email protected]>
Fri, 8 Nov 2019 18:44:20 +0000 (15:44 -0300)
committerAlvaro Herrera <[email protected]>
Fri, 8 Nov 2019 18:44:20 +0000 (15:44 -0300)
Add some support for automatically showing backtraces in certain error
situations in the server.  Backtraces are shown on assertion failure;
also, a new setting backtrace_functions can be set to a list of C
function names, and all ereport()s and elog()s from the mentioned
functions will have backtraces generated.  Finally, the function
errbacktrace() can be manually added to an ereport() call to generate a
backtrace for that call.

Authors: Peter Eisentraut, Álvaro Herrera
Discussion: https://postgr.es/m//5f48cb47-bf1e-05b6-7aae-3bf2cd01586d@2ndquadrant.com
Discussion: https://postgr.es/m/CAMsr+YGL+yfWE=JvbUbnpWtrRZNey7hJ07+zT4bYJdVp4Szdrg@mail.gmail.com

configure
configure.in
doc/src/sgml/config.sgml
src/backend/utils/error/assert.c
src/backend/utils/error/elog.c
src/backend/utils/misc/guc.c
src/include/pg_config.h.in
src/include/utils/elog.h
src/include/utils/guc.h

index 7312bd7a7a04ba3fffd30f8baac34717ebbee1ce..d6ce39452561b6b7dca04d1a00aafa8d6c05d437 100755 (executable)
--- a/configure
+++ b/configure
@@ -11607,6 +11607,63 @@ if test "$ac_res" != no; then :
 
 fi
 
+# *BSD:
+{ $as_echo "$as_me:${as_lineno-$LINENO}: checking for library containing backtrace_symbols" >&5
+$as_echo_n "checking for library containing backtrace_symbols... " >&6; }
+if ${ac_cv_search_backtrace_symbols+:} false; then :
+  $as_echo_n "(cached) " >&6
+else
+  ac_func_search_save_LIBS=$LIBS
+cat confdefs.h - <<_ACEOF >conftest.$ac_ext
+/* end confdefs.h.  */
+
+/* Override any GCC internal prototype to avoid an error.
+   Use char because int might match the return type of a GCC
+   builtin and then its argument prototype would still apply.  */
+#ifdef __cplusplus
+extern "C"
+#endif
+char backtrace_symbols ();
+int
+main ()
+{
+return backtrace_symbols ();
+  ;
+  return 0;
+}
+_ACEOF
+for ac_lib in '' execinfo; do
+  if test -z "$ac_lib"; then
+    ac_res="none required"
+  else
+    ac_res=-l$ac_lib
+    LIBS="-l$ac_lib  $ac_func_search_save_LIBS"
+  fi
+  if ac_fn_c_try_link "$LINENO"; then :
+  ac_cv_search_backtrace_symbols=$ac_res
+fi
+rm -f core conftest.err conftest.$ac_objext \
+    conftest$ac_exeext
+  if ${ac_cv_search_backtrace_symbols+:} false; then :
+  break
+fi
+done
+if ${ac_cv_search_backtrace_symbols+:} false; then :
+
+else
+  ac_cv_search_backtrace_symbols=no
+fi
+rm conftest.$ac_ext
+LIBS=$ac_func_search_save_LIBS
+fi
+{ $as_echo "$as_me:${as_lineno-$LINENO}: result: $ac_cv_search_backtrace_symbols" >&5
+$as_echo "$ac_cv_search_backtrace_symbols" >&6; }
+ac_res=$ac_cv_search_backtrace_symbols
+if test "$ac_res" != no; then :
+  test "$ac_res" = "none required" || LIBS="$ac_res $LIBS"
+
+fi
+
 
 if test "$with_readline" = yes; then
 
@@ -12705,7 +12762,7 @@ $as_echo "#define HAVE_STDBOOL_H 1" >>confdefs.h
 fi
 
 
-for ac_header in atomic.h copyfile.h fp_class.h getopt.h ieeefp.h ifaddrs.h langinfo.h mbarrier.h poll.h sys/epoll.h sys/ipc.h sys/prctl.h sys/procctl.h sys/pstat.h sys/resource.h sys/select.h sys/sem.h sys/shm.h sys/sockio.h sys/tas.h sys/un.h termios.h ucred.h utime.h wchar.h wctype.h
+for ac_header in atomic.h copyfile.h execinfo.h fp_class.h getopt.h ieeefp.h ifaddrs.h langinfo.h mbarrier.h poll.h sys/epoll.h sys/ipc.h sys/prctl.h sys/procctl.h sys/pstat.h sys/resource.h sys/select.h sys/sem.h sys/shm.h sys/sockio.h sys/tas.h sys/un.h termios.h ucred.h utime.h wchar.h wctype.h
 do :
   as_ac_Header=`$as_echo "ac_cv_header_$ac_header" | $as_tr_sh`
 ac_fn_c_check_header_mongrel "$LINENO" "$ac_header" "$as_ac_Header" "$ac_includes_default"
@@ -14935,7 +14992,7 @@ fi
 LIBS_including_readline="$LIBS"
 LIBS=`echo "$LIBS" | sed -e 's/-ledit//g' -e 's/-lreadline//g'`
 
-for ac_func in cbrt clock_gettime copyfile fdatasync getifaddrs getpeerucred getrlimit mbstowcs_l memset_s memmove poll posix_fallocate ppoll pstat pthread_is_threaded_np readlink setproctitle setproctitle_fast setsid shm_open strchrnul strsignal symlink sync_file_range uselocale utime utimes wcstombs_l
+for ac_func in backtrace_symbols cbrt clock_gettime copyfile fdatasync getifaddrs getpeerucred getrlimit mbstowcs_l memset_s memmove poll posix_fallocate ppoll pstat pthread_is_threaded_np readlink setproctitle setproctitle_fast setsid shm_open strchrnul strsignal symlink sync_file_range uselocale utime utimes wcstombs_l
 do :
   as_ac_var=`$as_echo "ac_cv_func_$ac_func" | $as_tr_sh`
 ac_fn_c_check_func "$LINENO" "$ac_func" "$as_ac_var"
index ea83d921cb61f5212670d8d1dbbca6384d343350..5bd31a876e8cfc23ad01336ffc572dffbd64b9f4 100644 (file)
@@ -1133,6 +1133,8 @@ AC_SEARCH_LIBS(sched_yield, rt)
 AC_SEARCH_LIBS(gethostbyname_r, nsl)
 # Cygwin:
 AC_SEARCH_LIBS(shmget, cygipc)
+# *BSD:
+AC_SEARCH_LIBS(backtrace_symbols, execinfo)
 
 if test "$with_readline" = yes; then
   PGAC_CHECK_READLINE
@@ -1275,6 +1277,7 @@ AC_HEADER_STDBOOL
 AC_CHECK_HEADERS(m4_normalize([
        atomic.h
        copyfile.h
+       execinfo.h
        fp_class.h
        getopt.h
        ieeefp.h
@@ -1608,6 +1611,7 @@ LIBS_including_readline="$LIBS"
 LIBS=`echo "$LIBS" | sed -e 's/-ledit//g' -e 's/-lreadline//g'`
 
 AC_CHECK_FUNCS(m4_normalize([
+       backtrace_symbols
        cbrt
        clock_gettime
        copyfile
index 46bc31de4c4fa96aa7771b1ca3a596b5a1a49269..a0e1925a1974304ec1d08b0bcf013e85a130c489 100644 (file)
@@ -9489,6 +9489,32 @@ dynamic_library_path = 'C:\tools\postgresql;H:\my_project\lib;$libdir'
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-backtrace-functions" xreflabel="backtrace_functions">
+      <term><varname>backtrace_functions</varname> (<type>string</type>)
+      <indexterm>
+        <primary><varname>backtrace_functions</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        This parameter contains a comma-separated list of C function names.
+        If an error is raised and the name of the internal C function where
+        the error happens matches a value in the list, then a backtrace is
+        written to the server log together with the error message.  This can
+        be used to debug specific areas of the source code.
+       </para>
+
+       <para>
+        Backtrace support is not available on all platforms, and the quality
+        of the backtraces depends on compilation options.
+       </para>
+
+       <para>
+        This parameter can only be set by superusers.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-ignore-system-indexes" xreflabel="ignore_system_indexes">
       <term><varname>ignore_system_indexes</varname> (<type>boolean</type>)
       <indexterm>
index 2050b4355d108d4b5ae050850d7d47e91c6db064..1069bbee81c38de65f8c08b8629f034b3cc47961 100644 (file)
@@ -18,6 +18,9 @@
 #include "postgres.h"
 
 #include <unistd.h>
+#ifdef HAVE_EXECINFO_H
+#include <execinfo.h>
+#endif
 
 /*
  * ExceptionalCondition - Handles the failure of an Assert()
@@ -42,6 +45,16 @@ ExceptionalCondition(const char *conditionName,
        /* Usually this shouldn't be needed, but make sure the msg went out */
        fflush(stderr);
 
+#ifdef HAVE_BACKTRACE_SYMBOLS
+       {
+               void       *buf[100];
+               int                     nframes;
+
+               nframes = backtrace(buf, lengthof(buf));
+               backtrace_symbols_fd(buf, nframes, fileno(stderr));
+       }
+#endif
+
 #ifdef SLEEP_ON_ASSERT
 
        /*
index 8b4720ef3abe9d852341f59f298ed34dddb54313..9ef4bc24727fbacab2ea8b62b9b38236b94eed3b 100644 (file)
@@ -62,6 +62,9 @@
 #ifdef HAVE_SYSLOG
 #include <syslog.h>
 #endif
+#ifdef HAVE_EXECINFO_H
+#include <execinfo.h>
+#endif
 
 #include "access/transam.h"
 #include "access/xact.h"
@@ -167,6 +170,7 @@ static char formatted_log_time[FORMATTED_TS_LEN];
 
 
 static const char *err_gettext(const char *str) pg_attribute_format_arg(1);
+static pg_noinline void set_backtrace(ErrorData *edata, int num_skip);
 static void set_errdata_field(MemoryContextData *cxt, char **ptr, const char *str);
 static void write_console(const char *line, int len);
 static void setup_formatted_log_time(void);
@@ -398,6 +402,32 @@ errstart(int elevel, const char *filename, int lineno,
        return true;
 }
 
+/*
+ * Checks whether the given funcname matches backtrace_functions; see
+ * check_backtrace_functions.
+ */
+static bool
+matches_backtrace_functions(const char *funcname)
+{
+       char       *p;
+
+       if (!backtrace_symbol_list || funcname == NULL || funcname[0] == '\0')
+               return false;
+
+       p = backtrace_symbol_list;
+       for (;;)
+       {
+               if (*p == '\0')         /* end of backtrace_symbol_list */
+                       break;
+
+               if (strcmp(funcname, p) == 0)
+                       return true;
+               p += strlen(p) + 1;
+       }
+
+       return false;
+}
+
 /*
  * errfinish --- end an error-reporting cycle
  *
@@ -424,6 +454,12 @@ errfinish(int dummy,...)
         */
        oldcontext = MemoryContextSwitchTo(ErrorContext);
 
+       if (!edata->backtrace &&
+               edata->funcname &&
+               backtrace_functions &&
+               matches_backtrace_functions(edata->funcname))
+               set_backtrace(edata, 2);
+
        /*
         * Call any context callback functions.  Errors occurring in callback
         * functions will be treated as recursive errors --- this ensures we will
@@ -488,6 +524,8 @@ errfinish(int dummy,...)
                pfree(edata->hint);
        if (edata->context)
                pfree(edata->context);
+       if (edata->backtrace)
+               pfree(edata->backtrace);
        if (edata->schema_name)
                pfree(edata->schema_name);
        if (edata->table_name)
@@ -798,6 +836,65 @@ errmsg(const char *fmt,...)
        return 0;                                       /* return value does not matter */
 }
 
+/*
+ * Add a backtrace to the containing ereport() call.  This is intended to be
+ * added temporarily during debugging.
+ */
+int
+errbacktrace(void)
+{
+       ErrorData   *edata = &errordata[errordata_stack_depth];
+       MemoryContext oldcontext;
+
+       Assert(false);
+
+       recursion_depth++;
+       CHECK_STACK_DEPTH();
+       oldcontext = MemoryContextSwitchTo(edata->assoc_context);
+
+       set_backtrace(edata, 1);
+
+       MemoryContextSwitchTo(oldcontext);
+       recursion_depth--;
+
+       return 0;
+}
+
+/*
+ * Compute backtrace data and add it to the supplied ErrorData.  num_skip
+ * specifies how many inner frames to skip.  Use this to avoid showing the
+ * internal backtrace support functions in the backtrace.  This requires that
+ * this and related functions are not inlined.
+ */
+static void
+set_backtrace(ErrorData *edata, int num_skip)
+{
+       StringInfoData errtrace;
+
+       initStringInfo(&errtrace);
+
+#ifdef HAVE_BACKTRACE_SYMBOLS
+       {
+               void       *buf[100];
+               int                     nframes;
+               char      **strfrms;
+
+               nframes = backtrace(buf, lengthof(buf));
+               strfrms = backtrace_symbols(buf, nframes);
+               if (strfrms == NULL)
+                       return;
+
+               for (int i = num_skip; i < nframes; i++)
+                       appendStringInfo(&errtrace, "\n%s", strfrms[i]);
+               free(strfrms);
+       }
+#else
+       appendStringInfoString(&errtrace,
+                                                  "backtrace generation is not supported by this installation");
+#endif
+
+       edata->backtrace = errtrace.data;
+}
 
 /*
  * errmsg_internal --- add a primary error message text to the current error
@@ -1353,6 +1450,11 @@ elog_finish(int elevel, const char *fmt,...)
        recursion_depth++;
        oldcontext = MemoryContextSwitchTo(edata->assoc_context);
 
+       if (!edata->backtrace &&
+               edata->funcname &&
+               matches_backtrace_functions(edata->funcname))
+               set_backtrace(edata, 2);
+
        edata->message_id = fmt;
        EVALUATE_MESSAGE(edata->domain, message, false, false);
 
@@ -1509,6 +1611,8 @@ CopyErrorData(void)
                newedata->hint = pstrdup(newedata->hint);
        if (newedata->context)
                newedata->context = pstrdup(newedata->context);
+       if (newedata->backtrace)
+               newedata->backtrace = pstrdup(newedata->backtrace);
        if (newedata->schema_name)
                newedata->schema_name = pstrdup(newedata->schema_name);
        if (newedata->table_name)
@@ -1547,6 +1651,8 @@ FreeErrorData(ErrorData *edata)
                pfree(edata->hint);
        if (edata->context)
                pfree(edata->context);
+       if (edata->backtrace)
+               pfree(edata->backtrace);
        if (edata->schema_name)
                pfree(edata->schema_name);
        if (edata->table_name)
@@ -1622,6 +1728,8 @@ ThrowErrorData(ErrorData *edata)
                newedata->hint = pstrdup(edata->hint);
        if (edata->context)
                newedata->context = pstrdup(edata->context);
+       if (edata->backtrace)
+               newedata->backtrace = pstrdup(edata->backtrace);
        /* assume message_id is not available */
        if (edata->schema_name)
                newedata->schema_name = pstrdup(edata->schema_name);
@@ -1689,6 +1797,8 @@ ReThrowError(ErrorData *edata)
                newedata->hint = pstrdup(newedata->hint);
        if (newedata->context)
                newedata->context = pstrdup(newedata->context);
+       if (newedata->backtrace)
+               newedata->backtrace = pstrdup(newedata->backtrace);
        if (newedata->schema_name)
                newedata->schema_name = pstrdup(newedata->schema_name);
        if (newedata->table_name)
@@ -2914,6 +3024,13 @@ send_message_to_server_log(ErrorData *edata)
                        append_with_tabs(&buf, edata->context);
                        appendStringInfoChar(&buf, '\n');
                }
+               if (edata->backtrace)
+               {
+                       log_line_prefix(&buf, edata);
+                       appendStringInfoString(&buf, _("BACKTRACE:  "));
+                       append_with_tabs(&buf, edata->backtrace);
+                       appendStringInfoChar(&buf, '\n');
+               }
                if (Log_error_verbosity >= PGERROR_VERBOSE)
                {
                        /* assume no newlines in funcname or filename... */
index e84c8cc4cfc9bb964278129add8ae5a7cc10e7fb..994bf37477a2d3d730480ca8507f9e2f8e54226e 100644 (file)
@@ -201,6 +201,8 @@ static bool check_cluster_name(char **newval, void **extra, GucSource source);
 static const char *show_unix_socket_permissions(void);
 static const char *show_log_file_mode(void);
 static const char *show_data_directory_mode(void);
+static bool check_backtrace_functions(char **newval, void **extra, GucSource source);
+static void assign_backtrace_functions(const char *newval, void *extra);
 static bool check_recovery_target_timeline(char **newval, void **extra, GucSource source);
 static void assign_recovery_target_timeline(const char *newval, void *extra);
 static bool check_recovery_target(char **newval, void **extra, GucSource source);
@@ -515,6 +517,8 @@ int                 log_temp_files = -1;
 double         log_statement_sample_rate = 1.0;
 double         log_xact_sample_rate = 0;
 int                    trace_recovery_messages = LOG;
+char      *backtrace_functions;
+char      *backtrace_symbol_list;
 
 int                    temp_file_limit = -1;
 
@@ -4224,6 +4228,17 @@ static struct config_string ConfigureNamesString[] =
                NULL, NULL, NULL
        },
 
+       {
+               {"backtrace_functions", PGC_SUSET, DEVELOPER_OPTIONS,
+                       gettext_noop("Log backtrace for errors in these functions."),
+                       NULL,
+                       GUC_NOT_IN_SAMPLE
+               },
+               &backtrace_functions,
+               "",
+               check_backtrace_functions, assign_backtrace_functions, NULL
+       },
+
        /* End-of-list marker */
        {
                {NULL, 0, 0, NULL, NULL}, NULL, NULL, NULL, NULL, NULL
@@ -11487,6 +11502,76 @@ show_data_directory_mode(void)
        return buf;
 }
 
+/*
+ * We split the input string, where commas separate function names
+ * and certain whitespace chars are ignored, into a \0-separated (and
+ * \0\0-terminated) list of function names.  This formulation allows
+ * easy scanning when an error is thrown while avoiding the use of
+ * non-reentrant strtok(), as well as keeping the output data in a
+ * single palloc() chunk.
+ */
+static bool
+check_backtrace_functions(char **newval, void **extra, GucSource source)
+{
+       int                     newvallen = strlen(*newval);
+       char       *someval;
+       int                     validlen;
+       int                     i;
+       int                     j;
+
+       /*
+        * Allow characters that can be C identifiers and commas as separators, as
+        * well as some whitespace for readability.
+        */
+       validlen = strspn(*newval,
+                                         "0123456789_"
+                                         "abcdefghijklmnopqrstuvwxyz"
+                                         "ABCDEFGHIJKLMNOPQRSTUVWXYZ"
+                                         ", \n\t");
+       if (validlen != newvallen)
+       {
+               GUC_check_errdetail("invalid character");
+               return false;
+       }
+
+       if (*newval[0] == '\0')
+       {
+               *extra = NULL;
+               return true;
+       }
+
+       /*
+        * Allocate space for the output and create the copy.  We could discount
+        * whitespace chars to save some memory, but it doesn't seem worth the
+        * trouble.
+        */
+       someval = guc_malloc(ERROR, newvallen + 1 + 1);
+       for (i = 0, j = 0; i < newvallen; i++)
+       {
+               if ((*newval)[i] == ',')
+                       someval[j++] = '\0';    /* next item */
+               else if ((*newval)[i] == ' ' ||
+                                (*newval)[i] == '\n' ||
+                                (*newval)[i] == '\t')
+                       ;       /* ignore these */
+               else
+                       someval[j++] = (*newval)[i];    /* copy anything else */
+       }
+
+       /* two \0s end the setting */
+       someval[j] = '\0';
+       someval[j + 1] = '\0';
+
+       *extra = someval;
+       return true;
+}
+
+static void
+assign_backtrace_functions(const char *newval, void *extra)
+{
+       backtrace_symbol_list = (char *) extra;
+}
+
 static bool
 check_recovery_target_timeline(char **newval, void **extra, GucSource source)
 {
index 2bf506033dfed39b8a57ad23b411c4744ff53a18..a56161cf289122eded1744328197d86f0bc525f3 100644 (file)
@@ -96,6 +96,9 @@
 /* Define to 1 if you have the <atomic.h> header file. */
 #undef HAVE_ATOMIC_H
 
+/* Define to 1 if you have the `backtrace_symbols' function. */
+#undef HAVE_BACKTRACE_SYMBOLS
+
 /* Define to 1 if you have the `BIO_get_data' function. */
 #undef HAVE_BIO_GET_DATA
 
 /* Define to 1 if you have the `explicit_bzero' function. */
 #undef HAVE_EXPLICIT_BZERO
 
+/* Define to 1 if you have the <execinfo.h> header file. */
+#undef HAVE_EXECINFO_H
+
 /* Define to 1 if you have the `fdatasync' function. */
 #undef HAVE_FDATASYNC
 
index 47412a831f096acb84c84fb09ee577820d479766..9ab4b5470b7d06c8e999c19e8889eaac2090d9ac 100644 (file)
@@ -189,6 +189,8 @@ extern int  errcontext_msg(const char *fmt,...) pg_attribute_printf(1, 2);
 extern int     errhidestmt(bool hide_stmt);
 extern int     errhidecontext(bool hide_ctx);
 
+extern int     errbacktrace(void);
+
 extern int     errfunction(const char *funcname);
 extern int     errposition(int cursorpos);
 
@@ -392,6 +394,7 @@ typedef struct ErrorData
        char       *detail_log;         /* detail error message for server log only */
        char       *hint;                       /* hint message */
        char       *context;            /* context message */
+       char       *backtrace;          /* backtrace */
        const char *message_id;         /* primary message's id (original string) */
        char       *schema_name;        /* name of schema */
        char       *table_name;         /* name of table */
index 9aa3d02596529dd33262ad9601546166f53821ae..50098e63feab3f440b1370ff33e88488927d551a 100644 (file)
@@ -256,6 +256,8 @@ extern int  log_min_duration_statement;
 extern int     log_temp_files;
 extern double log_statement_sample_rate;
 extern double log_xact_sample_rate;
+extern char *backtrace_functions;
+extern char *backtrace_symbol_list;
 
 extern int     temp_file_limit;