Merge pull request #10025 from opensourcerouting/xref-backtrace

lib: backtraces for specific log messages

doc/developer/building-frr-for-archlinux.rst

@@ -11,7 +11,9 @@ Installing Dependencies
       git autoconf automake libtool make cmake pcre readline texinfo \
       pkg-config pam json-c bison flex python-pytest \
       c-ares python python2-ipaddress python-sphinx \
-      net-snmp perl libcap libelf
+      net-snmp perl libcap libelf libunwind
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-centos7.rst

@@ -22,7 +22,9 @@ Add packages:
       readline-devel texinfo net-snmp-devel groff pkgconfig \
       json-c-devel pam-devel bison flex pytest c-ares-devel \
       python-devel python-sphinx libcap-devel \
-      elfutils-libelf-devel
+      elfutils-libelf-devel libunwind-devel
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-centos8.rst

@@ -15,7 +15,9 @@ Add packages:
       automake libtool make readline-devel texinfo net-snmp-devel pkgconfig \
       groff pkgconfig json-c-devel pam-devel bison flex python2-pytest \
       c-ares-devel python2-devel libcap-devel \
-      elfutils-libelf-devel
+      elfutils-libelf-devel libunwind-devel
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-debian9.rst

@@ -11,7 +11,9 @@ Add packages:
    sudo apt-get install git autoconf automake libtool make \
      libreadline-dev texinfo libjson-c-dev pkg-config bison flex \
      libc-ares-dev python3-dev python3-pytest python3-sphinx build-essential \
-     libsnmp-dev libcap-dev libelf-dev
+     libsnmp-dev libcap-dev libelf-dev libunwind-dev
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-fedora.rst

@@ -15,7 +15,9 @@ Installing Dependencies
      readline-devel texinfo net-snmp-devel groff pkgconfig json-c-devel \
      pam-devel python3-pytest bison flex c-ares-devel python3-devel \
      python3-sphinx perl-core patch libcap-devel \
-     elfutils-libelf-devel
+     elfutils-libelf-devel libunwind-devel
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-freebsd10.rst

@@ -17,7 +17,9 @@ is first package install and asked)
 ::
 
     pkg install git autoconf automake libtool gmake json-c pkgconf \
-        bison flex py36-pytest c-ares python3.6 py36-sphinx
+        bison flex py36-pytest c-ares python3.6 py36-sphinx libunwind
+
+.. include:: building-libunwind-note.rst
 
 Make sure there is no /usr/bin/flex preinstalled (and use the newly
 installed in /usr/local/bin): (FreeBSD frequently provides a older flex

doc/developer/building-frr-for-freebsd11.rst

@@ -17,7 +17,9 @@ is first package install and asked)
 .. code-block:: shell
 
    pkg install git autoconf automake libtool gmake json-c pkgconf \
-      bison flex py36-pytest c-ares python3.6 py36-sphinx texinfo
+      bison flex py36-pytest c-ares python3.6 py36-sphinx texinfo libunwind
+
+.. include:: building-libunwind-note.rst
 
 Make sure there is no /usr/bin/flex preinstalled (and use the newly
 installed in /usr/local/bin): (FreeBSD frequently provides a older flex

doc/developer/building-frr-for-opensuse.rst

@@ -14,7 +14,9 @@ Installing Dependencies
      readline-devel texinfo net-snmp-devel groff pkgconfig libjson-c-devel\
      pam-devel python3-pytest bison flex c-ares-devel python3-devel\
      python3-Sphinx perl patch libcap-devel libyang-devel \
-     libelf-devel
+     libelf-devel libunwind-devel
+
+.. include:: building-libunwind-note.rst
 
 Building & Installing FRR
 -------------------------

doc/developer/building-frr-for-ubuntu1804.rst

@@ -15,7 +15,9 @@ Installing Dependencies
       pkg-config libpam0g-dev libjson-c-dev bison flex \
       libc-ares-dev python3-dev python3-sphinx \
       install-info build-essential libsnmp-dev perl libcap-dev \
-      libelf-dev
+      libelf-dev libunwind-dev
+
+.. include:: building-libunwind-note.rst
 
 .. include:: building-libyang.rst
 

doc/developer/building-frr-for-ubuntu2004.rst

@@ -15,7 +15,9 @@ Installing Dependencies
       pkg-config libpam0g-dev libjson-c-dev bison flex \
       libc-ares-dev python3-dev python3-sphinx \
       install-info build-essential libsnmp-dev perl \
-      libcap-dev python2 libelf-dev
+      libcap-dev python2 libelf-dev libunwind-dev
+
+.. include:: building-libunwind-note.rst
 
 Note that Ubuntu 20 no longer installs python 2.x, so it must be
 installed explicitly. Ensure that your system has a symlink named

doc/developer/building-libunwind-note.rst

@@ -0,0 +1,6 @@
+.. note::
+
+   The ``libunwind`` library is optional but highly recommended, as it improves
+   backtraces printed for crashes and debugging.  However, if it is not
+   available for some reason, it can simply be left out without any loss of
+   functionality.

doc/developer/conf.py

@@ -136,6 +136,7 @@ language = None
 # directories to ignore when looking for source files.
 exclude_patterns = [
     "_build",
+    "building-libunwind-note.rst",
     "building-libyang.rst",
     "topotests-snippets.rst",
     "topotests-markers.rst",

doc/developer/subdir.am

@@ -23,6 +23,7 @@ dev_RSTFILES = \
 	doc/developer/building-frr-for-ubuntu1604.rst \
 	doc/developer/building-frr-for-ubuntu1804.rst \
 	doc/developer/building-frr-for-ubuntu2004.rst \
+	doc/developer/building-libunwind-note.rst \
 	doc/developer/building-libyang.rst \
 	doc/developer/building.rst \
 	doc/developer/cli.rst \

doc/user/basic.rst

@@ -244,6 +244,42 @@ Basic Config Commands
    Use unbuffered output for log and debug messages; normally there is
    some internal buffering.
 
+.. clicmd:: log unique-id
+
+   Include ``[XXXXX-XXXXX]`` log message unique identifier in the textual part
+   of log messages.  This is enabled by default, but can be disabled with
+   ``no log unique-id``.  Please make sure the IDs are enabled when including
+   logs for FRR bug reports.
+
+   The unique identifiers are automatically generated based on source code
+   file name, format string (before filling out) and severity.  They do not
+   change "randomly", but some cleanup work may cause large chunks of ID
+   changes between releases.  The IDs always start with a letter, consist of
+   letters and numbers (and a dash for readability), are case insensitive, and
+   ``I``, ``L``, ``O`` & ``U`` are excluded.
+
+   This option will not affect future logging targets which allow putting the
+   unique identifier in auxiliary metadata outside the log message text
+   content.  (No such logging target exists currently, but RFC5424 syslog and
+   systemd's journald both support it.)
+
+.. clicmd:: debug unique-id XXXXX-XXXXX backtrace
+
+   Print backtraces (call stack) for specific log messages, identified by
+   their unique ID (see above.)  Includes source code location and current
+   event handler being executed.  On some systems you may need to install a
+   `debug symbols` package to get proper function names rather than raw code
+   pointers.
+
+   This command can be issued inside and outside configuration mode, and is
+   saved to configuration only if it was given in configuration mode.
+
+   .. warning::
+
+      Printing backtraces can significantly slow down logging calls and cause
+      log files to quickly balloon in size.  Remember to disable backtraces
+      when they're no longer needed.
+
 .. clicmd:: service password-encryption
 
    Encrypt password.

lib/atomlist.c

@@ -18,6 +18,8 @@
 #include "config.h"
 #endif
 
+#include <assert.h>
+
 #include "atomlist.h"
 
 void atomlist_add_head(struct atomlist_head *h, struct atomlist_item *item)

lib/elf_py.c

@@ -636,6 +636,9 @@ static Elf_Scn *elf_find_addr(struct elffile *ef, uint64_t addr, size_t *idx)
 		Elf_Scn *scn = elf_getscn(ef->elf, i);
 		GElf_Shdr _shdr, *shdr = gelf_getshdr(scn, &_shdr);
 
+		/* virtual address is kinda meaningless for TLS sections */
+		if (shdr->sh_flags & SHF_TLS)
+			continue;
 		if (addr < shdr->sh_addr ||
 		    addr >= shdr->sh_addr + shdr->sh_size)
 			continue;

lib/frrcu.h

@@ -17,6 +17,8 @@
 #ifndef _FRRCU_H
 #define _FRRCU_H
 
+#include <assert.h>
+
 #include "memory.h"
 #include "atomlist.h"
 

lib/log_vty.c

@@ -36,6 +36,8 @@
 DEFINE_HOOK(zlog_rotate, (), ());
 DEFINE_HOOK(zlog_cli_show, (struct vty * vty), (vty));
 
+static unsigned logmsgs_with_persist_bt;
+
 static const int log_default_lvl = LOG_DEBUG;
 
 static int log_config_stdout_lvl = ZLOG_DISABLED;
@@ -267,6 +269,44 @@ DEFUN_HIDDEN (no_config_log_monitor,
 	return CMD_SUCCESS;
 }
 
+DEFPY (debug_uid_backtrace,
+       debug_uid_backtrace_cmd,
+       "[no] debug unique-id UID backtrace",
+       NO_STR
+       DEBUG_STR
+       "Options per individual log message, by unique ID\n"
+       "Log message unique ID (XXXXX-XXXXX)\n"
+       "Add backtrace to log when message is printed\n")
+{
+	struct xrefdata search, *xrd;
+	struct xrefdata_logmsg *xrdl;
+	uint8_t flag;
+
+	strlcpy(search.uid, uid, sizeof(search.uid));
+	xrd = xrefdata_uid_find(&xrefdata_uid, &search);
+
+	if (!xrd) {
+		vty_out(vty, "%% no log message with ID \"%s\" found\n", uid);
+		return CMD_WARNING;
+	}
+	if (xrd->xref->type != XREFT_LOGMSG) {
+		vty_out(vty, "%% ID \"%s\" is not a log message\n", uid);
+		return CMD_WARNING;
+	}
+	xrdl = container_of(xrd, struct xrefdata_logmsg, xrefdata);
+
+	flag = (vty->node == CONFIG_NODE) ? LOGMSG_FLAG_PERSISTENT
+					  : LOGMSG_FLAG_EPHEMERAL;
+
+	if ((xrdl->fl_print_bt & flag) == (no ? 0 : flag))
+		return CMD_SUCCESS;
+	if (flag == LOGMSG_FLAG_PERSISTENT)
+		logmsgs_with_persist_bt += no ? -1 : 1;
+
+	xrdl->fl_print_bt ^= flag;
+	return CMD_SUCCESS;
+}
+
 static int set_log_file(struct zlog_cfg_file *target, struct vty *vty,
 			const char *fname, int loglevel)
 {
@@ -751,6 +791,24 @@ void log_config_write(struct vty *vty)
 		vty_out(vty, "no log error-category\n");
 	if (!zlog_get_prefix_xid())
 		vty_out(vty, "no log unique-id\n");
+
+	if (logmsgs_with_persist_bt) {
+		struct xrefdata *xrd;
+		struct xrefdata_logmsg *xrdl;
+
+		vty_out(vty, "!\n");
+
+		frr_each (xrefdata_uid, &xrefdata_uid, xrd) {
+			if (xrd->xref->type != XREFT_LOGMSG)
+				continue;
+
+			xrdl = container_of(xrd, struct xrefdata_logmsg,
+					    xrefdata);
+			if (xrdl->fl_print_bt & LOGMSG_FLAG_PERSISTENT)
+				vty_out(vty, "debug unique-id %s backtrace\n",
+					xrd->uid);
+		}
+	}
 }
 
 static int log_vty_init(const char *progname, const char *protoname,
@@ -801,4 +859,7 @@ void log_cmd_init(void)
 	install_element(CONFIG_NODE, &config_log_filterfile_cmd);
 	install_element(CONFIG_NODE, &no_config_log_filterfile_cmd);
 	install_element(CONFIG_NODE, &log_immediate_mode_cmd);
+
+	install_element(ENABLE_NODE, &debug_uid_backtrace_cmd);
+	install_element(CONFIG_NODE, &debug_uid_backtrace_cmd);
 }

lib/typerb.h

@@ -20,6 +20,7 @@
 #ifndef _FRR_TYPERB_H
 #define _FRR_TYPERB_H
 
+#include <string.h>
 #include "typesafe.h"
 
 #ifdef __cplusplus

lib/typesafe.c

@@ -20,6 +20,7 @@
 
 #include <stdlib.h>
 #include <string.h>
+#include <assert.h>
 
 #include "typesafe.h"
 #include "memory.h"

lib/typesafe.h

@@ -20,7 +20,6 @@
 #include <stddef.h>
 #include <stdint.h>
 #include <stdbool.h>
-#include <assert.h>
 #include "compiler.h"
 
 #ifdef __cplusplus

lib/xref.c

@@ -35,6 +35,8 @@
 struct xref_block *xref_blocks;
 static struct xref_block **xref_block_last = &xref_blocks;
 
+struct xrefdata_uid_head xrefdata_uid = INIT_RBTREE_UNIQ(xrefdata_uid);
+
 static void base32(uint8_t **inpos, int *bitpos,
 		   char *out, size_t n_chars)
 {
@@ -109,6 +111,8 @@ static void xref_add_one(const struct xref *xref)
 	base32(&h, &bitpos, &xrefdata->uid[0], 5);
 	xrefdata->uid[5] = '-';
 	base32(&h, &bitpos, &xrefdata->uid[6], 5);
+
+	xrefdata_uid_add(&xrefdata_uid, xrefdata);
 }
 
 void xref_gcc_workaround(const struct xref *xref)

lib/xref.h

@@ -22,6 +22,7 @@
 #include <limits.h>
 #include <errno.h>
 #include "compiler.h"
+#include "typesafe.h"
 
 #ifdef __cplusplus
 extern "C" {
@@ -63,6 +64,8 @@ struct xref {
 	/* type-specific bits appended by embedding this struct */
 };
 
+PREDECL_RBTREE_UNIQ(xrefdata_uid);
+
 struct xrefdata {
 	/* pointer back to the const part;  this will be initialized at
 	 * program startup by xref_block_add().  (Creating structs with
@@ -88,8 +91,18 @@ struct xrefdata {
 	uint32_t hashu32[2];
 
 	/* -- 32 bytes (on 64bit) -- */
+	struct xrefdata_uid_item xui;
 };
 
+static inline int xrefdata_uid_cmp(const struct xrefdata *a,
+				   const struct xrefdata *b)
+{
+	return strcmp(a->uid, b->uid);
+}
+
+DECLARE_RBTREE_UNIQ(xrefdata_uid, struct xrefdata, xui, xrefdata_uid_cmp);
+extern struct xrefdata_uid_head xrefdata_uid;
+
 /* linker "magic" is used to create an array of pointers to struct xref.
  * the result is a contiguous block of pointers, each pointing to an xref
  * somewhere in the code.  The linker gives us start and end pointers, we

lib/zlog.c

@@ -47,12 +47,19 @@
 #include <mach/mach_traps.h>
 #endif
 
+#ifdef HAVE_LIBUNWIND
+#define UNW_LOCAL_ONLY
+#include <libunwind.h>
+#include <dlfcn.h>
+#endif
+
 #include "memory.h"
 #include "atomlist.h"
 #include "printfrr.h"
 #include "frrcu.h"
 #include "zlog.h"
 #include "libfrr_trace.h"
+#include "thread.h"
 
 DEFINE_MTYPE_STATIC(LIB, LOG_MESSAGE,  "log message");
 DEFINE_MTYPE_STATIC(LIB, LOG_TLSBUF,   "log thread-local buffer");
@@ -508,6 +515,87 @@ static void vzlog_tls(struct zlog_tls *zlog_tls, const struct xref_logmsg *xref,
 		XFREE(MTYPE_LOG_MESSAGE, msg->text);
 }
 
+static void zlog_backtrace_msg(const struct xref_logmsg *xref, int prio)
+{
+	struct thread *tc = pthread_getspecific(thread_current);
+	const char *uid = xref->xref.xrefdata->uid;
+	bool found_thread = false;
+
+	zlog(prio, "| (%s) message in thread %jd, at %s(), %s:%d", uid,
+	     zlog_gettid(), xref->xref.func, xref->xref.file, xref->xref.line);
+
+#ifdef HAVE_LIBUNWIND
+	const char *threadfunc = tc ? tc->xref->funcname : NULL;
+	bool found_caller = false;
+	unw_cursor_t cursor;
+	unw_context_t uc;
+	unw_word_t ip, off, sp;
+	Dl_info dlinfo;
+
+	unw_getcontext(&uc);
+
+	unw_init_local(&cursor, &uc);
+	while (unw_step(&cursor) > 0) {
+		char buf[96], name[128] = "?";
+		bool is_thread = false;
+
+		unw_get_reg(&cursor, UNW_REG_IP, &ip);
+		unw_get_reg(&cursor, UNW_REG_SP, &sp);
+
+		if (unw_is_signal_frame(&cursor))
+			zlog(prio, "| (%s)    ---- signal ----", uid);
+
+		if (!unw_get_proc_name(&cursor, buf, sizeof(buf), &off)) {
+			if (!strcmp(buf, xref->xref.func))
+				found_caller = true;
+			if (threadfunc && !strcmp(buf, threadfunc))
+				found_thread = is_thread = true;
+
+			snprintf(name, sizeof(name), "%s+%#lx", buf, (long)off);
+		}
+
+		if (!found_caller)
+			continue;
+
+		if (dladdr((void *)ip, &dlinfo))
+			zlog(prio, "| (%s) %-36s %16lx+%08lx %16lx %s", uid,
+			     name, (long)dlinfo.dli_fbase,
+			     (long)ip - (long)dlinfo.dli_fbase, (long)sp,
+			     dlinfo.dli_fname);
+		else
+			zlog(prio, "| (%s) %-36s %16lx %16lx", uid, name,
+			     (long)ip, (long)sp);
+
+		if (is_thread)
+			zlog(prio, "| (%s) ^- scheduled from %s(), %s:%u", uid,
+			     tc->xref->xref.func, tc->xref->xref.file,
+			     tc->xref->xref.line);
+	}
+#elif defined(HAVE_GLIBC_BACKTRACE)
+	void *frames[64];
+	char **names = NULL;
+	int n_frames, i;
+
+	n_frames = backtrace(frames, array_size(frames));
+	if (n_frames < 0)
+		n_frames = 0;
+	if (n_frames)
+		names = backtrace_symbols(frames, n_frames);
+
+	for (i = 0; i < n_frames; i++) {
+		void *retaddr = frames[i];
+		char *loc = names[i];
+
+		zlog(prio, "| (%s) %16lx %-36s", uid, (long)retaddr, loc);
+	}
+	free(names);
+#endif
+	if (!found_thread && tc)
+		zlog(prio, "| (%s) scheduled from %s(), %s:%u", uid,
+		     tc->xref->xref.func, tc->xref->xref.file,
+		     tc->xref->xref.line);
+}
+
 void vzlogx(const struct xref_logmsg *xref, int prio,
 	    const char *fmt, va_list ap)
 {
@@ -545,6 +633,15 @@ void vzlogx(const struct xref_logmsg *xref, int prio,
 		vzlog_tls(zlog_tls, xref, prio, fmt, ap);
 	else
 		vzlog_notls(xref, prio, fmt, ap);
+
+	if (xref) {
+		struct xrefdata_logmsg *xrdl;
+
+		xrdl = container_of(xref->xref.xrefdata, struct xrefdata_logmsg,
+				    xrefdata);
+		if (xrdl->fl_print_bt)
+			zlog_backtrace_msg(xref, prio);
+	}
 }
 
 void zlog_sigsafe(const char *text, size_t len)

lib/zlog.h

@@ -54,10 +54,14 @@ struct xref_logmsg {
 	const char *args;
 };
 
+/* whether flag was added in config mode or enable mode */
+#define LOGMSG_FLAG_EPHEMERAL	(1 << 0)
+#define LOGMSG_FLAG_PERSISTENT	(1 << 1)
+
 struct xrefdata_logmsg {
 	struct xrefdata xrefdata;
 
-	/* nothing more here right now */
+	uint8_t fl_print_bt;
 };
 
 /* These functions are set up to write to stdout/stderr without explicit
@@ -94,15 +98,19 @@ static inline void zlog_ref(const struct xref_logmsg *xref,
 
 #define _zlog_ecref(ec_, prio, msg, ...)                                       \
 	do {                                                                   \
-		static struct xrefdata _xrefdata = {                           \
-			.xref = NULL,                                          \
-			.uid = {},                                             \
-			.hashstr = (msg),                                      \
-			.hashu32 = {(prio), (ec_)},                            \
+		static struct xrefdata_logmsg _xrefdata = {                    \
+			.xrefdata =                                            \
+				{                                              \
+					.xref = NULL,                          \
+					.uid = {},                             \
+					.hashstr = (msg),                      \
+					.hashu32 = {(prio), (ec_)},            \
+				},                                             \
 		};                                                             \
 		static const struct xref_logmsg _xref __attribute__(           \
 			(used)) = {                                            \
-			.xref = XREF_INIT(XREFT_LOGMSG, &_xrefdata, __func__), \
+			.xref = XREF_INIT(XREFT_LOGMSG, &_xrefdata.xrefdata,   \
+					  __func__),                           \
 			.fmtstring = (msg),                                    \
 			.priority = (prio),                                    \
 			.ec = (ec_),                                           \