lib: add `debug uid XXXXX-XXXXX backtrace`

Looks much prettier if `libunwind` is available, but works with glibc or
libexecinfo's `backtrace()` too.

Signed-off-by: David Lamparter <equinox@opensourcerouting.org>

diff --git a/lib/log_vty.c b/lib/log_vty.c
index cbb8de897646231f2a6fe45a50650c1fa8405d27..99113235537efe73bcbd6823114c8f34dfb75ec6 100644 (file)
--- a/lib/log_vty.c
+++ b/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);
 }

diff --git a/lib/zlog.c b/lib/zlog.c
index 6fd52cae62b744efa9c5289dacc5f5483ffd93b2..1b0751559dc7a9a2af90d8a91386e2a65b5d70ff 100644 (file)
--- a/lib/zlog.c
+++ b/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)

diff --git a/lib/zlog.h b/lib/zlog.h
index d9c8952ac553c8c6c66a4fa321e610d86867e820..6e84fe892372dd6f7fdce33989ad6a426a79405e 100644 (file)
--- a/lib/zlog.h
+++ b/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_),                                           \