diff mbox series

[ovs-dev,v2] backtrace: Extent the backtrace functionality

Message ID 20230317150225.743812-1-amusil@redhat.com
State Changes Requested
Headers show
Series [ovs-dev,v2] backtrace: Extent the backtrace functionality | expand

Checks

Context Check Description
ovsrobot/apply-robot success apply and check: success
ovsrobot/github-robot-_Build_and_Test success github build: passed
ovsrobot/intel-ovs-compilation success test: success

Commit Message

Ales Musil March 17, 2023, 3:02 p.m. UTC
Use the backtrace functions that is provided by libc,
this allows us to get backtrace that is independent of
the current memory map of the process. Which in turn can
be used for debugging/tracing purpose. The backtrace
is not 100% accurate due to various optimizations, most
notably "-fomit-frame-pointer" and LTO. This might result
that the line in source file doesn't correspond to the
real line. However, it should be able to pinpoint at least
the function where the backtrace was called.

The usage for SIGSEGV is determined during compilation
based on available libraries. Libunwind has higher priority
if both methods are available to keep the compatibility with
current behavior.

The backtrace is not marked as signal safe however the backtrace
manual page gives more detailed explanation why it might be the
case [0]. Load the "libgcc" or equivalent in advance within the
"fatal_signal_init" which should ensure that subsequent calls
to backtrace* do not call malloc and are signal safe.

The typical backtrace will look similar to the one below:
/lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
/lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
/lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
/lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d) [0x7fc5db563a8d]
ovsdb-server(+0xa661) [0x562cfce2e661]
ovsdb-server(+0x7e39) [0x562cfce2be39]
/lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
/lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
ovsdb-server(+0x8c35) [0x562cfce2cc35]

backtrace.h elaborates on how to effectively get the line
information associated with the addressed presented in the
backtrace.

[0]
backtrace() and backtrace_symbols_fd() don't call malloc()
explicitly, but they are part of libgcc, which gets loaded
dynamically when first used.  Dynamic loading usually triggers
a call to malloc(3).  If you need certain calls to these two
functions to not allocate memory (in signal handlers, for
example), you need to make sure libgcc is loaded beforehand

Reported-at: https://bugzilla.redhat.com/2177760
Signed-off-by: Ales Musil <amusil@redhat.com>
---
v2: Extend the current use of libunwind rather than replacing it.
---
 include/openvswitch/vlog.h |   4 +-
 lib/backtrace.c            |  77 +++++++++-------------------
 lib/backtrace.h            |  58 ++++++++++++---------
 lib/daemon-unix.c          |   1 -
 lib/fatal-signal.c         | 102 ++++++++++++++++++++++---------------
 lib/ovsdb-error.c          |  15 ++----
 lib/vlog.c                 |  14 ++---
 m4/openvswitch.m4          |   9 ++--
 tests/atlocal.in           |   2 +
 tests/daemon.at            |  71 ++++++++++++++++++++++++++
 10 files changed, 208 insertions(+), 145 deletions(-)

Comments

Aaron Conole March 22, 2023, 2 p.m. UTC | #1
Hi Ales,

Ales Musil <amusil@redhat.com> writes:

> Use the backtrace functions that is provided by libc,
> this allows us to get backtrace that is independent of
> the current memory map of the process. Which in turn can
> be used for debugging/tracing purpose. The backtrace
> is not 100% accurate due to various optimizations, most
> notably "-fomit-frame-pointer" and LTO. This might result
> that the line in source file doesn't correspond to the
> real line. However, it should be able to pinpoint at least
> the function where the backtrace was called.
>
> The usage for SIGSEGV is determined during compilation
> based on available libraries. Libunwind has higher priority
> if both methods are available to keep the compatibility with
> current behavior.
>
> The backtrace is not marked as signal safe however the backtrace
> manual page gives more detailed explanation why it might be the
> case [0]. Load the "libgcc" or equivalent in advance within the
> "fatal_signal_init" which should ensure that subsequent calls
> to backtrace* do not call malloc and are signal safe.
>
> The typical backtrace will look similar to the one below:
> /lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
> /lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
> /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
> /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d) [0x7fc5db563a8d]
> ovsdb-server(+0xa661) [0x562cfce2e661]
> ovsdb-server(+0x7e39) [0x562cfce2be39]
> /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
> /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
> ovsdb-server(+0x8c35) [0x562cfce2cc35]
>
> backtrace.h elaborates on how to effectively get the line
> information associated with the addressed presented in the
> backtrace.
>
> [0]
> backtrace() and backtrace_symbols_fd() don't call malloc()
> explicitly, but they are part of libgcc, which gets loaded
> dynamically when first used.  Dynamic loading usually triggers
> a call to malloc(3).  If you need certain calls to these two
> functions to not allocate memory (in signal handlers, for
> example), you need to make sure libgcc is loaded beforehand
>
> Reported-at: https://bugzilla.redhat.com/2177760
> Signed-off-by: Ales Musil <amusil@redhat.com>
> ---
> v2: Extend the current use of libunwind rather than replacing it.

Thanks for this.  Sorry for the quick review here - I've not gotten a
chance to get too in-depth.  Comments below.

> ---
>  include/openvswitch/vlog.h |   4 +-
>  lib/backtrace.c            |  77 +++++++++-------------------
>  lib/backtrace.h            |  58 ++++++++++++---------
>  lib/daemon-unix.c          |   1 -
>  lib/fatal-signal.c         | 102 ++++++++++++++++++++++---------------
>  lib/ovsdb-error.c          |  15 ++----
>  lib/vlog.c                 |  14 ++---
>  m4/openvswitch.m4          |   9 ++--
>  tests/atlocal.in           |   2 +
>  tests/daemon.at            |  71 ++++++++++++++++++++++++++
>  10 files changed, 208 insertions(+), 145 deletions(-)
>
> diff --git a/include/openvswitch/vlog.h b/include/openvswitch/vlog.h
> index e53ce6d81..98edc3452 100644
> --- a/include/openvswitch/vlog.h
> +++ b/include/openvswitch/vlog.h
> @@ -145,8 +145,8 @@ void vlog_set_syslog_method(const char *method);
>  /* Configure syslog target. */
>  void vlog_set_syslog_target(const char *target);
>  
> -/* Write directly to log file. */
> -void vlog_direct_write_to_log_file_unsafe(const char *s);
> +/* Return the current vlog file descriptor. */
> +int vlog_fd(void);

Why eliminate the direct write function?  Just because the
bactrace_symbols_fd() call?  Maybe we can have a function like:

void vlog_direct_write_backtrace_symbols(void *const *buffer, int size);

And then pass the symbols?  Or even have both functions but use
vlog_fd() only when we are going to call the backtrace function?

>  
>  /* Initialization. */
>  void vlog_init(void);
> diff --git a/lib/backtrace.c b/lib/backtrace.c
> index 2853d5ff1..69e1281b0 100644
> --- a/lib/backtrace.c
> +++ b/lib/backtrace.c
> @@ -32,12 +32,23 @@ VLOG_DEFINE_THIS_MODULE(backtrace);
>  void
>  backtrace_capture(struct backtrace *b)
>  {
> -    void *frames[BACKTRACE_MAX_FRAMES];
> -    int i;
> +    b->n_frames = backtrace(b->frames, BACKTRACE_MAX_FRAMES);
> +}
> +
> +void
> +backtrace_format(const struct backtrace *bt, struct ds *ds)
> +{
> +    if (bt->n_frames) {
> +        char **symbols = backtrace_symbols(bt->frames, bt->n_frames);
> +        if (!symbols) {
> +            return;
> +        }
> +
> +        for (int i = 0; i < bt->n_frames; i++) {
> +            ds_put_format(ds, "%s\n", symbols[i]);
> +        }
>  
> -    b->n_frames = backtrace(frames, BACKTRACE_MAX_FRAMES);
> -    for (i = 0; i < b->n_frames; i++) {
> -        b->frames[i] = (uintptr_t) frames[i];
> +        free(symbols);
>      }
>  }
>  
> @@ -47,23 +58,13 @@ backtrace_capture(struct backtrace *backtrace)
>  {
>      backtrace->n_frames = 0;
>  }
> -#endif
>  
> -static char *
> -backtrace_format(const struct backtrace *b, struct ds *ds)
> +void
> +backtrace_format(const struct backtrace *bt OVS_UNUSED, struct ds *ds)
>  {
> -    if (b->n_frames) {
> -        int i;
> -
> -        ds_put_cstr(ds, " (backtrace:");
> -        for (i = 0; i < b->n_frames; i++) {
> -            ds_put_format(ds, " 0x%08"PRIxPTR, b->frames[i]);
> -        }
> -        ds_put_cstr(ds, ")");
> -    }
> -
> -    return ds_cstr(ds);
> +    ds_put_cstr(ds, "backtrace() is not supported!\n");
>  }
> +#endif
>  
>  void
>  log_backtrace_at(const char *msg, const char *where)
> @@ -77,41 +78,9 @@ log_backtrace_at(const char *msg, const char *where)
>      }
>  
>      ds_put_cstr(&ds, where);
> -    VLOG_ERR("%s", backtrace_format(&b, &ds));
> +    ds_put_cstr(&ds, " backtrace:\n");
> +    backtrace_format(&b, &ds);
> +    VLOG_ERR("%s", ds_cstr_ro(&ds));
>  
>      ds_destroy(&ds);
>  }
> -
> -#ifdef HAVE_UNWIND
> -void
> -log_received_backtrace(int fd) {
> -    int byte_read;
> -    struct unw_backtrace backtrace[UNW_MAX_DEPTH];
> -
> -    VLOG_WARN("%s fd %d", __func__, fd);
> -    fcntl(fd, F_SETFL, O_NONBLOCK);
> -    memset(backtrace, 0, UNW_MAX_BUF);
> -
> -    byte_read = read(fd, backtrace, UNW_MAX_BUF);
> -    if (byte_read < 0) {
> -        VLOG_ERR("Read fd %d failed: %s", fd,
> -                 ovs_strerror(errno));
> -    } else if (byte_read > 0) {
> -        VLOG_WARN("SIGSEGV detected, backtrace:");
> -        for (int i = 0; i < UNW_MAX_DEPTH; i++) {
> -            if (backtrace[i].func[0] == 0) {
> -                break;
> -            }
> -            VLOG_WARN("0x%016"PRIxPTR" <%s+0x%"PRIxPTR">\n",
> -                      backtrace[i].ip,
> -                      backtrace[i].func,
> -                      backtrace[i].offset);
> -        }
> -    }
> -}
> -#else /* !HAVE_UNWIND */
> -void
> -log_received_backtrace(int daemonize_fd OVS_UNUSED) {
> -    VLOG_WARN("Backtrace using libunwind not supported.");
> -}
> -#endif /* HAVE_UNWIND */
> diff --git a/lib/backtrace.h b/lib/backtrace.h
> index 5708bf9c6..ecb3c464c 100644
> --- a/lib/backtrace.h
> +++ b/lib/backtrace.h
> @@ -36,41 +36,53 @@
>   *       log_backtrace_msg("your message");         <-- with a message
>   *
>   *
> - * A typical log will look like the following. The hex numbers listed after
> - * "backtrace" are the addresses of the backtrace.
> + * A typical backtrace will look like the following example:
> + * /lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
> + * /lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
> + * /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
> + * /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d)
> + * [0x7fc5db563a8d]
> + * ovsdb-server(+0xa661) [0x562cfce2e661]
> + * ovsdb-server(+0x7e39) [0x562cfce2be39]
> + * /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
> + * /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
> + * ovsdb-server(+0x8c35) [0x562cfce2cc35]
>   *
> - * 2014-03-13T23:18:11.979Z|00002|backtrace(revalidator_6)|ERR|lib/dpif-netdev.c:1312: (backtrace: 0x00521f57 0x00460365 0x00463ea4 0x0046470b 0x0043b32d 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3 0x2b5b3ac94e9a 0x2b5b3b4a33fd)
> + * GDB can be used to view the exact line of the code for particular backtrace.
> + * One thing to keep in mind is that the lines in source files might not
> + * 100% correspond with the backtrace due to various optimizations as LTO etc.
> + * (The effect can be seen in this example).
>   *
> - * The following bash command can be used to  view backtrace in
> - * a more readable form.
> - * addr2line -p -e vswitchd/ovs-vswitchd <cut-and-paste back traces>
> + * Assuming that debuginfo for the library or binary is installed load it to
> + * GDB:
> + * $ gdb ovsdb-server
> + * (gdb) list *(+0x7e39)
> + * 0x7e39 is in main (ovsdb/ovsdb-server.c:278).
> + * (gdb) list *(+0xa661)
> + * 0xa661 is in commit_txn (ovsdb/ovsdb-server.c:1173)
>   *
> - * An typical run and output will look like:
> - * addr2line -p -e vswitchd/ovs-vswitchd  0x00521f57 0x00460365 0x00463ea4
> - * 0x0046470b 0x0043b32d 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3
> - * 0x2b5b3ac94e9a 0x2b5b3b4a33fd
> + * $ gdb /lib64/libovsdb-3.1.so.0
> + * (gdb) list *(ovsdb_txn_propose_commit_block+0x8d)
> + * 0x3aa8d is in ovsdb_txn_propose_commit_block (ovsdb/transaction.c:1328)
> + * (gdb) list *(ovsdb_txn_complete+0x7b)
> + * 0x3947b is in ovsdb_txn_complete (./include/openvswitch/list.h:321)
>   *
> - * openvswitch/lib/backtrace.c:33
> - * openvswitch/lib/dpif-netdev.c:1312
> - * openvswitch/lib/dpif.c:937
> - * openvswitch/lib/dpif.c:1258
> - * openvswitch/ofproto/ofproto-dpif-upcall.c:1440
> - * openvswitch/ofproto/ofproto-dpif-upcall.c:1595
> - * openvswitch/ofproto/ofproto-dpif-upcall.c:160
> - * openvswitch/ofproto/ofproto-dpif-upcall.c:717
> - * openvswitch/lib/ovs-thread.c:268
> - * ??:0
> - * ??:0
> + * $ gdb /lib64/libopenvswitch-3.1.so.0
> + * (gdb) list *(log_backtrace_at+0x57)
> + * 0x999e7 is in log_backtrace_at (lib/backtrace.c:77)
> + * (gdb) list *(backtrace_capture+0x1e)
> + * 0x98dfe is in backtrace_capture (lib/backtrace.c:35)
>   */
>  
>  #define log_backtrace() log_backtrace_at(NULL, OVS_SOURCE_LOCATOR);
>  #define log_backtrace_msg(msg) log_backtrace_at(msg, OVS_SOURCE_LOCATOR);
>  
>  #define BACKTRACE_MAX_FRAMES 31
> +#define BACKTRACE_DUMP_MSG "SIGSEGV detected, backtrace:\n"
>  
>  struct backtrace {
>      int n_frames;
> -    uintptr_t frames[BACKTRACE_MAX_FRAMES];
> +    void *frames[BACKTRACE_MAX_FRAMES];
>  };
>  
>  #ifdef HAVE_UNWIND
> @@ -88,6 +100,6 @@ struct unw_backtrace {
>  
>  void backtrace_capture(struct backtrace *);
>  void log_backtrace_at(const char *msg, const char *where);
> -void log_received_backtrace(int fd);
> +void backtrace_format(const struct backtrace *bt, struct ds *ds);
>  
>  #endif /* backtrace.h */
> diff --git a/lib/daemon-unix.c b/lib/daemon-unix.c
> index 1a7ba427d..68706f73a 100644
> --- a/lib/daemon-unix.c
> +++ b/lib/daemon-unix.c
> @@ -395,7 +395,6 @@ monitor_daemon(pid_t daemon_pid)
>                      }
>                  }
>  
> -                log_received_backtrace(daemonize_fd);
>                  close(daemonize_fd);
>                  daemonize_fd = -1;
>  
> diff --git a/lib/fatal-signal.c b/lib/fatal-signal.c
> index bbb31ef27..07b088f69 100644
> --- a/lib/fatal-signal.c
> +++ b/lib/fatal-signal.c
> @@ -35,8 +35,8 @@
>  
>  #include "openvswitch/type-props.h"
>  
> -#ifdef HAVE_UNWIND
> -#include "daemon-private.h"
> +#ifdef HAVE_BACKTRACE
> +#include <execinfo.h>
>  #endif
>  
>  #ifndef SIG_ATOMIC_MAX
> @@ -94,6 +94,13 @@ fatal_signal_init(void)
>          inited = true;
>  
>          ovs_mutex_init_recursive(&mutex);
> +
> +        /* The dummy backtrace is needed see comment for
> +         * send_backtrace_to_monitor(). */
> +        struct backtrace dummy_bt;
> +        backtrace_capture(&dummy_bt);
> +        VLOG_DBG("Load needed libraries by capturing dummy backtrace,"
> +                 " n_frames=%d", dummy_bt.n_frames);
>  #ifndef _WIN32
>          xpipe_nonblocking(signal_fds);
>  #else
> @@ -175,20 +182,21 @@ llong_to_hex_str(unsigned long long value, char *str)
>      return i + 1;
>  }
>  
> -/* Send the backtrace buffer to monitor thread.
> +/* Print backtrace.
>   *
>   * Note that this runs in the signal handling context, any system
>   * library functions used here must be async-signal-safe.
>   */
>  static inline void
> -send_backtrace_to_monitor(void) {
> +print_backtrace(void) {
>      /* volatile added to prevent a "clobbered" error on ppc64le with gcc */
>      volatile int dep;
>      struct unw_backtrace unw_bt[UNW_MAX_DEPTH];
>      unw_cursor_t cursor;
>      unw_context_t uc;
>  
> -    if (daemonize_fd == -1) {
> +    int log_fd = vlog_fd();
> +    if (!log_fd) {

I think it is possible for log_fd to be '0'.  Such a number is a valid
value for the fd (although, I agree it probably would be a rare case for
this to happen).  So this check would be 'if (log_fd < 0) {'

>          return;
>      }
>  
> @@ -204,44 +212,58 @@ send_backtrace_to_monitor(void) {
>          dep++;
>      }
>  
> -    if (monitor) {

Hrrm.. did we lose the ability to send the backtrace back to the monitor
with this patchset?  It looks like now the daemon that is failing to
segv direct writes the data to the logfile, did I get it right?  If so,
why change this behavior?

> -        ignore(write(daemonize_fd, unw_bt,
> -                     dep * sizeof(struct unw_backtrace)));
> -    } else {
> -        /* Since there is no monitor daemon running, write backtrace
> -         * in current process.
> -         */
> -        char str[] = "SIGSEGV detected, backtrace:\n";
> -        char ip_str[16], offset_str[6];
> -        char line[64], fn_name[UNW_MAX_FUNCN];
> -
> -        vlog_direct_write_to_log_file_unsafe(str);
> -
> -        for (int i = 0; i < dep; i++) {
> -            memset(line, 0, sizeof line);
> -            memset(fn_name, 0, sizeof fn_name);
> -            memset(offset_str, 0, sizeof offset_str);
> -            memset(ip_str, ' ', sizeof ip_str);
> -            ip_str[sizeof(ip_str) - 1] = 0;
> -
> -            llong_to_hex_str(unw_bt[i].ip, ip_str);
> -            llong_to_hex_str(unw_bt[i].offset, offset_str);
> -
> -            strcat(line, "0x");
> -            strcat(line, ip_str);
> -            strcat(line, "<");
> -            memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
> -            strcat(line, fn_name);
> -            strcat(line, "+0x");
> -            strcat(line, offset_str);
> -            strcat(line, ">\n");
> -            vlog_direct_write_to_log_file_unsafe(line);
> -        }
> +    char ip_str[16], offset_str[6];
> +    char line[64], fn_name[UNW_MAX_FUNCN];
> +
> +    ignore(write(log_fd, BACKTRACE_DUMP_MSG, strlen(BACKTRACE_DUMP_MSG)));
> +
> +    for (int i = 0; i < dep; i++) {
> +        memset(line, 0, sizeof line);
> +        memset(fn_name, 0, sizeof fn_name);
> +        memset(offset_str, 0, sizeof offset_str);
> +        memset(ip_str, ' ', sizeof ip_str);
> +        ip_str[sizeof(ip_str) - 1] = 0;
> +
> +        llong_to_hex_str(unw_bt[i].ip, ip_str);
> +        llong_to_hex_str(unw_bt[i].offset, offset_str);
> +
> +        strcat(line, "0x");
> +        strcat(line, ip_str);
> +        strcat(line, "<");
> +        memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
> +        strcat(line, fn_name);
> +        strcat(line, "+0x");
> +        strcat(line, offset_str);
> +        strcat(line, ">\n");
> +        ignore(write(log_fd, line, strlen(line)));
>      }
>  }
> +#elif HAVE_BACKTRACE
> +/* Print backtrace.
> + *
> + * Note that this runs in the signal handling context, any system
> + * library functions used here must be async-signal-safe.
> + * backtrace() is only signal safe if the "libgcc" or equivalent was loaded
> + * before the signal handler. In order to keep it safe the fatal_signal_init()
> + * should always call backtrace_capture which will ensure that "libgcc" or
> + * equivlent is loaded.
> + */
> +static inline void
> +print_backtrace(void) {
> +    int log_fd = vlog_fd();
> +    if (!log_fd) {
> +        return;
> +    }
> +
> +    struct backtrace bt;
> +    backtrace_capture(&bt);
> +
> +    ignore(write(log_fd, BACKTRACE_DUMP_MSG, strlen(BACKTRACE_DUMP_MSG)));
> +    backtrace_symbols_fd(bt.frames, bt.n_frames, log_fd);
> +}
>  #else
>  static inline void
> -send_backtrace_to_monitor(void) {
> +print_backtrace(void) {
>      /* Nothing. */
>  }
>  #endif
> @@ -261,7 +283,7 @@ fatal_signal_handler(int sig_nr)
>  #ifndef _WIN32
>      if (sig_nr == SIGSEGV) {
>          signal(sig_nr, SIG_DFL); /* Set it back immediately. */
> -        send_backtrace_to_monitor();
> +        print_backtrace();
>          raise(sig_nr);
>      }
>      ignore(write(signal_fds[1], "", 1));
> diff --git a/lib/ovsdb-error.c b/lib/ovsdb-error.c
> index a75ad36b7..2cd6242f3 100644
> --- a/lib/ovsdb-error.c
> +++ b/lib/ovsdb-error.c
> @@ -139,17 +139,6 @@ ovsdb_internal_error(struct ovsdb_error *inner_error,
>          va_end(args);
>      }
>  
> -    backtrace_capture(&backtrace);
> -    if (backtrace.n_frames) {
> -        int i;
> -
> -        ds_put_cstr(&ds, " (backtrace:");
> -        for (i = 0; i < backtrace.n_frames; i++) {
> -            ds_put_format(&ds, " 0x%08"PRIxPTR, backtrace.frames[i]);
> -        }
> -        ds_put_char(&ds, ')');
> -    }
> -
>      ds_put_format(&ds, " (%s %s)", program_name, VERSION);
>  
>      if (inner_error) {
> @@ -158,6 +147,10 @@ ovsdb_internal_error(struct ovsdb_error *inner_error,
>          free(s);
>      }
>  
> +    ds_put_cstr(&ds, ", backtrace:");
> +    backtrace_capture(&backtrace);
> +    backtrace_format(&backtrace, &ds);
> +
>      error = ovsdb_error("internal error", "%s", ds_cstr(&ds));
>  
>      ds_destroy(&ds);
> diff --git a/lib/vlog.c b/lib/vlog.c
> index 9ddea48b8..b40c6909d 100644
> --- a/lib/vlog.c
> +++ b/lib/vlog.c
> @@ -649,19 +649,11 @@ vlog_set_syslog_target(const char *target)
>      ovs_rwlock_unlock(&pattern_rwlock);
>  }
>  
> -/*
> - * This function writes directly to log file without using async writer or
> - * taking a lock.  Caller must hold 'log_file_mutex' or be sure that it's
> - * not necessary.  Could be used in exceptional cases like dumping of backtrace
> - * on fatal signals.
> - */
> -void
> -vlog_direct_write_to_log_file_unsafe(const char *s)
> +int
> +vlog_fd(void)
>      OVS_NO_THREAD_SAFETY_ANALYSIS
>  {
> -    if (log_fd >= 0) {
> -        ignore(write(log_fd, s, strlen(s)));
> -    }
> +    return log_fd;
>  }
>  
>  /* Returns 'false' if 'facility' is not a valid string. If 'facility'
> diff --git a/m4/openvswitch.m4 b/m4/openvswitch.m4
> index 14d9249b8..f4943b140 100644
> --- a/m4/openvswitch.m4
> +++ b/m4/openvswitch.m4
> @@ -359,9 +359,12 @@ AC_DEFUN([OVS_CHECK_DBDIR],
>  
>  dnl Defines HAVE_BACKTRACE if backtrace() is found.
>  AC_DEFUN([OVS_CHECK_BACKTRACE],
> -  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace],
> -                  [AC_DEFINE([HAVE_BACKTRACE], [1],
> -                             [Define to 1 if you have backtrace(3).])])])
> +  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace], [HAVE_BACKTRACE=yes], [HAVE_BACKTRACE=no])
> +   if test "$HAVE_BACKTRACE" = "yes"; then
> +     AC_DEFINE([HAVE_BACKTRACE], [1], [Define to 1 if you have backtrace(3).])
> +   fi
> +   AM_CONDITIONAL([HAVE_BACKTRACE], [test "$HAVE_BACKTRACE" = "yes"])
> +   AC_SUBST([HAVE_BACKTRACE])])
>  
>  dnl Defines HAVE_PERF_EVENT if linux/perf_event.h is found.
>  AC_DEFUN([OVS_CHECK_PERF_EVENT],
> diff --git a/tests/atlocal.in b/tests/atlocal.in
> index 859668586..18d5efae0 100644
> --- a/tests/atlocal.in
> +++ b/tests/atlocal.in
> @@ -2,6 +2,8 @@
>  HAVE_OPENSSL='@HAVE_OPENSSL@'
>  OPENSSL_SUPPORTS_SNI='@OPENSSL_SUPPORTS_SNI@'
>  HAVE_UNBOUND='@HAVE_UNBOUND@'
> +HAVE_BACKTRACE='@HAVE_BACKTRACE@'
> +HAVE_UNWIND='@HAVE_UNWIND@'
>  EGREP='@EGREP@'
>  PYTHON3='@PYTHON3@'
>  CFLAGS='@CFLAGS@'
> diff --git a/tests/daemon.at b/tests/daemon.at
> index d7981f9d2..bce54aa5b 100644
> --- a/tests/daemon.at
> +++ b/tests/daemon.at
> @@ -234,3 +234,74 @@ OVS_WAIT_UNTIL([sc query ovsdb-server | grep STATE | grep STOPPED > /dev/null 2>
>  AT_CHECK([sc delete ovsdb-server], [0], [[[SC]] DeleteService SUCCESS
>  ])
>  AT_CLEANUP
> +
> +
> +AT_SETUP([backtrace --detach])
> +AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" = "no"])
> +
> +# This test intentionally causes SIGSEGV, so make Address Sanitizer ignore it.
> +ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
> +
> +# Skip it if UB Sanitizer is being used.  There's no way to disable the
> +# SEGV check at runtime.
> +AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
> +
> +# Start the daemon and make sure that the pidfile exists immediately.
> +# We don't wait for the pidfile to get created because the daemon is
> +# supposed to do so before the parent exits.
> +AT_CHECK([ovsdb-server --detach --no-chdir --pidfile --no-db --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
> +
> +AT_CHECK([test -s ovsdb-server.pid])
> +child=$(cat ovsdb-server.pid)
> +
> +OVS_WAIT_WHILE([kill -SEGV $child])
> +OVS_WAIT_UNTIL([grep -q "^SIGSEGV detected, backtrace:" ovsdb-server.log])
> +AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing dummy backtrace" ovsdb-server.log])
> +
> +AT_CLEANUP
> +
> +AT_SETUP([backtrace --detach --monitor])
> +AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" = "no"])
> +
> +# This test intentionally causes SIGSEGV, so make Address Sanitizer ignore it.
> +ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
> +
> +# Skip it if UB Sanitizer is being used.  There's no way to disable the
> +# SEGV check at runtime.
> +AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
> +
> +on_exit 'kill $(cat *.pid)'
> +
> +# Start the daemon and make sure that the pidfile exists immediately.
> +# We don't wait for the pidfile to get created because the daemon is
> +# supposed to do so before the parent exits.
> +AT_CHECK([ovsdb-server --detach --monitor --no-chdir --pidfile --no-db --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
> +AT_CHECK([test -s ovsdb-server.pid])
> +child=$(cat ovsdb-server.pid)
> +
> +# Check process naming and ancestry.
> +monitor=$(parent_pid $child)
> +check_process_name $child ovsdb-server
> +check_ancestors $child $monitor 1
> +
> +# Kill the daemon process, making it look like a segfault,
> +# and wait for a new daemon process to get spawned.
> +AT_CHECK([kill -SEGV $child], [0])
> +OVS_WAIT_WHILE([kill -0 $child])
> +OVS_WAIT_UNTIL([test -s ovsdb-server.pid && test `cat ovsdb-server.pid` != $child])
> +child2=$(cat ovsdb-server.pid)
> +
> +# Check process naming and ancestry.
> +check_process_name $child2 ovsdb-server
> +check_ancestors $child2 $monitor 1
> +
> +# Kill the daemon process with SIGTERM, and wait for the daemon
> +# and the monitor processes to go away and the pidfile to get deleted.
> +AT_CHECK([kill $child2])
> +OVS_WAIT_WHILE([kill -0 $monitor || kill -0 $child2 || test -e ovsdb-server.pid])
> +
> +AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing dummy backtrace" ovsdb-server.log])
> +AT_CHECK([grep -q "^SIGSEGV detected, backtrace:" ovsdb-server.log])
> +AT_CHECK([grep -q "daemon_unix(monitor)|ERR|1 crashes: pid .* died, killed (Segmentation fault), core dumped, restarting" ovsdb-server.log])
> +
> +AT_CLEANUP
Ales Musil March 23, 2023, 6:14 a.m. UTC | #2
On Wed, Mar 22, 2023 at 3:00 PM Aaron Conole <aconole@redhat.com> wrote:

> Hi Ales,
>
>
Hi Aaron,


> Ales Musil <amusil@redhat.com> writes:
>
> > Use the backtrace functions that is provided by libc,
> > this allows us to get backtrace that is independent of
> > the current memory map of the process. Which in turn can
> > be used for debugging/tracing purpose. The backtrace
> > is not 100% accurate due to various optimizations, most
> > notably "-fomit-frame-pointer" and LTO. This might result
> > that the line in source file doesn't correspond to the
> > real line. However, it should be able to pinpoint at least
> > the function where the backtrace was called.
> >
> > The usage for SIGSEGV is determined during compilation
> > based on available libraries. Libunwind has higher priority
> > if both methods are available to keep the compatibility with
> > current behavior.
> >
> > The backtrace is not marked as signal safe however the backtrace
> > manual page gives more detailed explanation why it might be the
> > case [0]. Load the "libgcc" or equivalent in advance within the
> > "fatal_signal_init" which should ensure that subsequent calls
> > to backtrace* do not call malloc and are signal safe.
> >
> > The typical backtrace will look similar to the one below:
> > /lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
> > /lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
> > /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
> > /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d)
> [0x7fc5db563a8d]
> > ovsdb-server(+0xa661) [0x562cfce2e661]
> > ovsdb-server(+0x7e39) [0x562cfce2be39]
> > /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
> > /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
> > ovsdb-server(+0x8c35) [0x562cfce2cc35]
> >
> > backtrace.h elaborates on how to effectively get the line
> > information associated with the addressed presented in the
> > backtrace.
> >
> > [0]
> > backtrace() and backtrace_symbols_fd() don't call malloc()
> > explicitly, but they are part of libgcc, which gets loaded
> > dynamically when first used.  Dynamic loading usually triggers
> > a call to malloc(3).  If you need certain calls to these two
> > functions to not allocate memory (in signal handlers, for
> > example), you need to make sure libgcc is loaded beforehand
> >
> > Reported-at: https://bugzilla.redhat.com/2177760
> > Signed-off-by: Ales Musil <amusil@redhat.com>
> > ---
> > v2: Extend the current use of libunwind rather than replacing it.
>
> Thanks for this.  Sorry for the quick review here - I've not gotten a
> chance to get too in-depth.  Comments below.
>

Thanks for the feedback, please see the reply below.


>
> > ---
> >  include/openvswitch/vlog.h |   4 +-
> >  lib/backtrace.c            |  77 +++++++++-------------------
> >  lib/backtrace.h            |  58 ++++++++++++---------
> >  lib/daemon-unix.c          |   1 -
> >  lib/fatal-signal.c         | 102 ++++++++++++++++++++++---------------
> >  lib/ovsdb-error.c          |  15 ++----
> >  lib/vlog.c                 |  14 ++---
> >  m4/openvswitch.m4          |   9 ++--
> >  tests/atlocal.in           |   2 +
> >  tests/daemon.at            |  71 ++++++++++++++++++++++++++
> >  10 files changed, 208 insertions(+), 145 deletions(-)
> >
> > diff --git a/include/openvswitch/vlog.h b/include/openvswitch/vlog.h
> > index e53ce6d81..98edc3452 100644
> > --- a/include/openvswitch/vlog.h
> > +++ b/include/openvswitch/vlog.h
> > @@ -145,8 +145,8 @@ void vlog_set_syslog_method(const char *method);
> >  /* Configure syslog target. */
> >  void vlog_set_syslog_target(const char *target);
> >
> > -/* Write directly to log file. */
> > -void vlog_direct_write_to_log_file_unsafe(const char *s);
> > +/* Return the current vlog file descriptor. */
> > +int vlog_fd(void);
>
> Why eliminate the direct write function?  Just because the
> bactrace_symbols_fd() call?  Maybe we can have a function like:
>
> void vlog_direct_write_backtrace_symbols(void *const *buffer, int size);
>
> And then pass the symbols?  Or even have both functions but use
> vlog_fd() only when we are going to call the backtrace function?
>

We can have an additional function that will write the symbols, however
it is a bit unfortunate that we need to define that function twice because
backtrace_symbols_fd() might not be available. To me it felt like this is
better, but I don't have any hard preference in the end.


>
> >
> >  /* Initialization. */
> >  void vlog_init(void);
> > diff --git a/lib/backtrace.c b/lib/backtrace.c
> > index 2853d5ff1..69e1281b0 100644
> > --- a/lib/backtrace.c
> > +++ b/lib/backtrace.c
> > @@ -32,12 +32,23 @@ VLOG_DEFINE_THIS_MODULE(backtrace);
> >  void
> >  backtrace_capture(struct backtrace *b)
> >  {
> > -    void *frames[BACKTRACE_MAX_FRAMES];
> > -    int i;
> > +    b->n_frames = backtrace(b->frames, BACKTRACE_MAX_FRAMES);
> > +}
> > +
> > +void
> > +backtrace_format(const struct backtrace *bt, struct ds *ds)
> > +{
> > +    if (bt->n_frames) {
> > +        char **symbols = backtrace_symbols(bt->frames, bt->n_frames);
> > +        if (!symbols) {
> > +            return;
> > +        }
> > +
> > +        for (int i = 0; i < bt->n_frames; i++) {
> > +            ds_put_format(ds, "%s\n", symbols[i]);
> > +        }
> >
> > -    b->n_frames = backtrace(frames, BACKTRACE_MAX_FRAMES);
> > -    for (i = 0; i < b->n_frames; i++) {
> > -        b->frames[i] = (uintptr_t) frames[i];
> > +        free(symbols);
> >      }
> >  }
> >
> > @@ -47,23 +58,13 @@ backtrace_capture(struct backtrace *backtrace)
> >  {
> >      backtrace->n_frames = 0;
> >  }
> > -#endif
> >
> > -static char *
> > -backtrace_format(const struct backtrace *b, struct ds *ds)
> > +void
> > +backtrace_format(const struct backtrace *bt OVS_UNUSED, struct ds *ds)
> >  {
> > -    if (b->n_frames) {
> > -        int i;
> > -
> > -        ds_put_cstr(ds, " (backtrace:");
> > -        for (i = 0; i < b->n_frames; i++) {
> > -            ds_put_format(ds, " 0x%08"PRIxPTR, b->frames[i]);
> > -        }
> > -        ds_put_cstr(ds, ")");
> > -    }
> > -
> > -    return ds_cstr(ds);
> > +    ds_put_cstr(ds, "backtrace() is not supported!\n");
> >  }
> > +#endif
> >
> >  void
> >  log_backtrace_at(const char *msg, const char *where)
> > @@ -77,41 +78,9 @@ log_backtrace_at(const char *msg, const char *where)
> >      }
> >
> >      ds_put_cstr(&ds, where);
> > -    VLOG_ERR("%s", backtrace_format(&b, &ds));
> > +    ds_put_cstr(&ds, " backtrace:\n");
> > +    backtrace_format(&b, &ds);
> > +    VLOG_ERR("%s", ds_cstr_ro(&ds));
> >
> >      ds_destroy(&ds);
> >  }
> > -
> > -#ifdef HAVE_UNWIND
> > -void
> > -log_received_backtrace(int fd) {
> > -    int byte_read;
> > -    struct unw_backtrace backtrace[UNW_MAX_DEPTH];
> > -
> > -    VLOG_WARN("%s fd %d", __func__, fd);
> > -    fcntl(fd, F_SETFL, O_NONBLOCK);
> > -    memset(backtrace, 0, UNW_MAX_BUF);
> > -
> > -    byte_read = read(fd, backtrace, UNW_MAX_BUF);
> > -    if (byte_read < 0) {
> > -        VLOG_ERR("Read fd %d failed: %s", fd,
> > -                 ovs_strerror(errno));
> > -    } else if (byte_read > 0) {
> > -        VLOG_WARN("SIGSEGV detected, backtrace:");
> > -        for (int i = 0; i < UNW_MAX_DEPTH; i++) {
> > -            if (backtrace[i].func[0] == 0) {
> > -                break;
> > -            }
> > -            VLOG_WARN("0x%016"PRIxPTR" <%s+0x%"PRIxPTR">\n",
> > -                      backtrace[i].ip,
> > -                      backtrace[i].func,
> > -                      backtrace[i].offset);
> > -        }
> > -    }
> > -}
> > -#else /* !HAVE_UNWIND */
> > -void
> > -log_received_backtrace(int daemonize_fd OVS_UNUSED) {
> > -    VLOG_WARN("Backtrace using libunwind not supported.");
> > -}
> > -#endif /* HAVE_UNWIND */
> > diff --git a/lib/backtrace.h b/lib/backtrace.h
> > index 5708bf9c6..ecb3c464c 100644
> > --- a/lib/backtrace.h
> > +++ b/lib/backtrace.h
> > @@ -36,41 +36,53 @@
> >   *       log_backtrace_msg("your message");         <-- with a message
> >   *
> >   *
> > - * A typical log will look like the following. The hex numbers listed
> after
> > - * "backtrace" are the addresses of the backtrace.
> > + * A typical backtrace will look like the following example:
> > + * /lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e)
> [0x7fc5db298dfe]
> > + * /lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57)
> [0x7fc5db2999e7]
> > + * /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
> > + * /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d)
> > + * [0x7fc5db563a8d]
> > + * ovsdb-server(+0xa661) [0x562cfce2e661]
> > + * ovsdb-server(+0x7e39) [0x562cfce2be39]
> > + * /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
> > + * /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
> > + * ovsdb-server(+0x8c35) [0x562cfce2cc35]
> >   *
> > - *
> 2014-03-13T23:18:11.979Z|00002|backtrace(revalidator_6)|ERR|lib/dpif-netdev.c:1312:
> (backtrace: 0x00521f57 0x00460365 0x00463ea4 0x0046470b 0x0043b32d
> 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3 0x2b5b3ac94e9a 0x2b5b3b4a33fd)
> > + * GDB can be used to view the exact line of the code for particular
> backtrace.
> > + * One thing to keep in mind is that the lines in source files might not
> > + * 100% correspond with the backtrace due to various optimizations as
> LTO etc.
> > + * (The effect can be seen in this example).
> >   *
> > - * The following bash command can be used to  view backtrace in
> > - * a more readable form.
> > - * addr2line -p -e vswitchd/ovs-vswitchd <cut-and-paste back traces>
> > + * Assuming that debuginfo for the library or binary is installed load
> it to
> > + * GDB:
> > + * $ gdb ovsdb-server
> > + * (gdb) list *(+0x7e39)
> > + * 0x7e39 is in main (ovsdb/ovsdb-server.c:278).
> > + * (gdb) list *(+0xa661)
> > + * 0xa661 is in commit_txn (ovsdb/ovsdb-server.c:1173)
> >   *
> > - * An typical run and output will look like:
> > - * addr2line -p -e vswitchd/ovs-vswitchd  0x00521f57 0x00460365
> 0x00463ea4
> > - * 0x0046470b 0x0043b32d 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3
> > - * 0x2b5b3ac94e9a 0x2b5b3b4a33fd
> > + * $ gdb /lib64/libovsdb-3.1.so.0
> > + * (gdb) list *(ovsdb_txn_propose_commit_block+0x8d)
> > + * 0x3aa8d is in ovsdb_txn_propose_commit_block
> (ovsdb/transaction.c:1328)
> > + * (gdb) list *(ovsdb_txn_complete+0x7b)
> > + * 0x3947b is in ovsdb_txn_complete (./include/openvswitch/list.h:321)
> >   *
> > - * openvswitch/lib/backtrace.c:33
> > - * openvswitch/lib/dpif-netdev.c:1312
> > - * openvswitch/lib/dpif.c:937
> > - * openvswitch/lib/dpif.c:1258
> > - * openvswitch/ofproto/ofproto-dpif-upcall.c:1440
> > - * openvswitch/ofproto/ofproto-dpif-upcall.c:1595
> > - * openvswitch/ofproto/ofproto-dpif-upcall.c:160
> > - * openvswitch/ofproto/ofproto-dpif-upcall.c:717
> > - * openvswitch/lib/ovs-thread.c:268
> > - * ??:0
> > - * ??:0
> > + * $ gdb /lib64/libopenvswitch-3.1.so.0
> > + * (gdb) list *(log_backtrace_at+0x57)
> > + * 0x999e7 is in log_backtrace_at (lib/backtrace.c:77)
> > + * (gdb) list *(backtrace_capture+0x1e)
> > + * 0x98dfe is in backtrace_capture (lib/backtrace.c:35)
> >   */
> >
> >  #define log_backtrace() log_backtrace_at(NULL, OVS_SOURCE_LOCATOR);
> >  #define log_backtrace_msg(msg) log_backtrace_at(msg,
> OVS_SOURCE_LOCATOR);
> >
> >  #define BACKTRACE_MAX_FRAMES 31
> > +#define BACKTRACE_DUMP_MSG "SIGSEGV detected, backtrace:\n"
> >
> >  struct backtrace {
> >      int n_frames;
> > -    uintptr_t frames[BACKTRACE_MAX_FRAMES];
> > +    void *frames[BACKTRACE_MAX_FRAMES];
> >  };
> >
> >  #ifdef HAVE_UNWIND
> > @@ -88,6 +100,6 @@ struct unw_backtrace {
> >
> >  void backtrace_capture(struct backtrace *);
> >  void log_backtrace_at(const char *msg, const char *where);
> > -void log_received_backtrace(int fd);
> > +void backtrace_format(const struct backtrace *bt, struct ds *ds);
> >
> >  #endif /* backtrace.h */
> > diff --git a/lib/daemon-unix.c b/lib/daemon-unix.c
> > index 1a7ba427d..68706f73a 100644
> > --- a/lib/daemon-unix.c
> > +++ b/lib/daemon-unix.c
> > @@ -395,7 +395,6 @@ monitor_daemon(pid_t daemon_pid)
> >                      }
> >                  }
> >
> > -                log_received_backtrace(daemonize_fd);
> >                  close(daemonize_fd);
> >                  daemonize_fd = -1;
> >
> > diff --git a/lib/fatal-signal.c b/lib/fatal-signal.c
> > index bbb31ef27..07b088f69 100644
> > --- a/lib/fatal-signal.c
> > +++ b/lib/fatal-signal.c
> > @@ -35,8 +35,8 @@
> >
> >  #include "openvswitch/type-props.h"
> >
> > -#ifdef HAVE_UNWIND
> > -#include "daemon-private.h"
> > +#ifdef HAVE_BACKTRACE
> > +#include <execinfo.h>
> >  #endif
> >
> >  #ifndef SIG_ATOMIC_MAX
> > @@ -94,6 +94,13 @@ fatal_signal_init(void)
> >          inited = true;
> >
> >          ovs_mutex_init_recursive(&mutex);
> > +
> > +        /* The dummy backtrace is needed see comment for
> > +         * send_backtrace_to_monitor(). */
> > +        struct backtrace dummy_bt;
> > +        backtrace_capture(&dummy_bt);
> > +        VLOG_DBG("Load needed libraries by capturing dummy backtrace,"
> > +                 " n_frames=%d", dummy_bt.n_frames);
> >  #ifndef _WIN32
> >          xpipe_nonblocking(signal_fds);
> >  #else
> > @@ -175,20 +182,21 @@ llong_to_hex_str(unsigned long long value, char
> *str)
> >      return i + 1;
> >  }
> >
> > -/* Send the backtrace buffer to monitor thread.
> > +/* Print backtrace.
> >   *
> >   * Note that this runs in the signal handling context, any system
> >   * library functions used here must be async-signal-safe.
> >   */
> >  static inline void
> > -send_backtrace_to_monitor(void) {
> > +print_backtrace(void) {
> >      /* volatile added to prevent a "clobbered" error on ppc64le with
> gcc */
> >      volatile int dep;
> >      struct unw_backtrace unw_bt[UNW_MAX_DEPTH];
> >      unw_cursor_t cursor;
> >      unw_context_t uc;
> >
> > -    if (daemonize_fd == -1) {
> > +    int log_fd = vlog_fd();
> > +    if (!log_fd) {
>
> I think it is possible for log_fd to be '0'.  Such a number is a valid
> value for the fd (although, I agree it probably would be a rare case for
> this to happen).  So this check would be 'if (log_fd < 0) {'
>

Right, I'll fix it in v3.


>
> >          return;
> >      }
> >
> > @@ -204,44 +212,58 @@ send_backtrace_to_monitor(void) {
> >          dep++;
> >      }
> >
> > -    if (monitor) {
>
> Hrrm.. did we lose the ability to send the backtrace back to the monitor
> with this patchset?  It looks like now the daemon that is failing to
> segv direct writes the data to the logfile, did I get it right?  If so,
> why change this behavior?
>


Unless I'm missing something we don't need it. AFAIU the log file is the
same for both
daemon and the monitor. So we can actually do the operation directly
without the need
to send it to monitor with the same result.


>
> > -        ignore(write(daemonize_fd, unw_bt,
> > -                     dep * sizeof(struct unw_backtrace)));
> > -    } else {
> > -        /* Since there is no monitor daemon running, write backtrace
> > -         * in current process.
> > -         */
> > -        char str[] = "SIGSEGV detected, backtrace:\n";
> > -        char ip_str[16], offset_str[6];
> > -        char line[64], fn_name[UNW_MAX_FUNCN];
> > -
> > -        vlog_direct_write_to_log_file_unsafe(str);
> > -
> > -        for (int i = 0; i < dep; i++) {
> > -            memset(line, 0, sizeof line);
> > -            memset(fn_name, 0, sizeof fn_name);
> > -            memset(offset_str, 0, sizeof offset_str);
> > -            memset(ip_str, ' ', sizeof ip_str);
> > -            ip_str[sizeof(ip_str) - 1] = 0;
> > -
> > -            llong_to_hex_str(unw_bt[i].ip, ip_str);
> > -            llong_to_hex_str(unw_bt[i].offset, offset_str);
> > -
> > -            strcat(line, "0x");
> > -            strcat(line, ip_str);
> > -            strcat(line, "<");
> > -            memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
> > -            strcat(line, fn_name);
> > -            strcat(line, "+0x");
> > -            strcat(line, offset_str);
> > -            strcat(line, ">\n");
> > -            vlog_direct_write_to_log_file_unsafe(line);
> > -        }
> > +    char ip_str[16], offset_str[6];
> > +    char line[64], fn_name[UNW_MAX_FUNCN];
> > +
> > +    ignore(write(log_fd, BACKTRACE_DUMP_MSG,
> strlen(BACKTRACE_DUMP_MSG)));
> > +
> > +    for (int i = 0; i < dep; i++) {
> > +        memset(line, 0, sizeof line);
> > +        memset(fn_name, 0, sizeof fn_name);
> > +        memset(offset_str, 0, sizeof offset_str);
> > +        memset(ip_str, ' ', sizeof ip_str);
> > +        ip_str[sizeof(ip_str) - 1] = 0;
> > +
> > +        llong_to_hex_str(unw_bt[i].ip, ip_str);
> > +        llong_to_hex_str(unw_bt[i].offset, offset_str);
> > +
> > +        strcat(line, "0x");
> > +        strcat(line, ip_str);
> > +        strcat(line, "<");
> > +        memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
> > +        strcat(line, fn_name);
> > +        strcat(line, "+0x");
> > +        strcat(line, offset_str);
> > +        strcat(line, ">\n");
> > +        ignore(write(log_fd, line, strlen(line)));
> >      }
> >  }
> > +#elif HAVE_BACKTRACE
> > +/* Print backtrace.
> > + *
> > + * Note that this runs in the signal handling context, any system
> > + * library functions used here must be async-signal-safe.
> > + * backtrace() is only signal safe if the "libgcc" or equivalent was
> loaded
> > + * before the signal handler. In order to keep it safe the
> fatal_signal_init()
> > + * should always call backtrace_capture which will ensure that "libgcc"
> or
> > + * equivlent is loaded.
> > + */
> > +static inline void
> > +print_backtrace(void) {
> > +    int log_fd = vlog_fd();
> > +    if (!log_fd) {
> > +        return;
> > +    }
> > +
> > +    struct backtrace bt;
> > +    backtrace_capture(&bt);
> > +
> > +    ignore(write(log_fd, BACKTRACE_DUMP_MSG,
> strlen(BACKTRACE_DUMP_MSG)));
> > +    backtrace_symbols_fd(bt.frames, bt.n_frames, log_fd);
> > +}
> >  #else
> >  static inline void
> > -send_backtrace_to_monitor(void) {
> > +print_backtrace(void) {
> >      /* Nothing. */
> >  }
> >  #endif
> > @@ -261,7 +283,7 @@ fatal_signal_handler(int sig_nr)
> >  #ifndef _WIN32
> >      if (sig_nr == SIGSEGV) {
> >          signal(sig_nr, SIG_DFL); /* Set it back immediately. */
> > -        send_backtrace_to_monitor();
> > +        print_backtrace();
> >          raise(sig_nr);
> >      }
> >      ignore(write(signal_fds[1], "", 1));
> > diff --git a/lib/ovsdb-error.c b/lib/ovsdb-error.c
> > index a75ad36b7..2cd6242f3 100644
> > --- a/lib/ovsdb-error.c
> > +++ b/lib/ovsdb-error.c
> > @@ -139,17 +139,6 @@ ovsdb_internal_error(struct ovsdb_error
> *inner_error,
> >          va_end(args);
> >      }
> >
> > -    backtrace_capture(&backtrace);
> > -    if (backtrace.n_frames) {
> > -        int i;
> > -
> > -        ds_put_cstr(&ds, " (backtrace:");
> > -        for (i = 0; i < backtrace.n_frames; i++) {
> > -            ds_put_format(&ds, " 0x%08"PRIxPTR, backtrace.frames[i]);
> > -        }
> > -        ds_put_char(&ds, ')');
> > -    }
> > -
> >      ds_put_format(&ds, " (%s %s)", program_name, VERSION);
> >
> >      if (inner_error) {
> > @@ -158,6 +147,10 @@ ovsdb_internal_error(struct ovsdb_error
> *inner_error,
> >          free(s);
> >      }
> >
> > +    ds_put_cstr(&ds, ", backtrace:");
> > +    backtrace_capture(&backtrace);
> > +    backtrace_format(&backtrace, &ds);
> > +
> >      error = ovsdb_error("internal error", "%s", ds_cstr(&ds));
> >
> >      ds_destroy(&ds);
> > diff --git a/lib/vlog.c b/lib/vlog.c
> > index 9ddea48b8..b40c6909d 100644
> > --- a/lib/vlog.c
> > +++ b/lib/vlog.c
> > @@ -649,19 +649,11 @@ vlog_set_syslog_target(const char *target)
> >      ovs_rwlock_unlock(&pattern_rwlock);
> >  }
> >
> > -/*
> > - * This function writes directly to log file without using async writer
> or
> > - * taking a lock.  Caller must hold 'log_file_mutex' or be sure that
> it's
> > - * not necessary.  Could be used in exceptional cases like dumping of
> backtrace
> > - * on fatal signals.
> > - */
> > -void
> > -vlog_direct_write_to_log_file_unsafe(const char *s)
> > +int
> > +vlog_fd(void)
> >      OVS_NO_THREAD_SAFETY_ANALYSIS
> >  {
> > -    if (log_fd >= 0) {
> > -        ignore(write(log_fd, s, strlen(s)));
> > -    }
> > +    return log_fd;
> >  }
> >
> >  /* Returns 'false' if 'facility' is not a valid string. If 'facility'
> > diff --git a/m4/openvswitch.m4 b/m4/openvswitch.m4
> > index 14d9249b8..f4943b140 100644
> > --- a/m4/openvswitch.m4
> > +++ b/m4/openvswitch.m4
> > @@ -359,9 +359,12 @@ AC_DEFUN([OVS_CHECK_DBDIR],
> >
> >  dnl Defines HAVE_BACKTRACE if backtrace() is found.
> >  AC_DEFUN([OVS_CHECK_BACKTRACE],
> > -  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace],
> > -                  [AC_DEFINE([HAVE_BACKTRACE], [1],
> > -                             [Define to 1 if you have
> backtrace(3).])])])
> > +  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace],
> [HAVE_BACKTRACE=yes], [HAVE_BACKTRACE=no])
> > +   if test "$HAVE_BACKTRACE" = "yes"; then
> > +     AC_DEFINE([HAVE_BACKTRACE], [1], [Define to 1 if you have
> backtrace(3).])
> > +   fi
> > +   AM_CONDITIONAL([HAVE_BACKTRACE], [test "$HAVE_BACKTRACE" = "yes"])
> > +   AC_SUBST([HAVE_BACKTRACE])])
> >
> >  dnl Defines HAVE_PERF_EVENT if linux/perf_event.h is found.
> >  AC_DEFUN([OVS_CHECK_PERF_EVENT],
> > diff --git a/tests/atlocal.in b/tests/atlocal.in
> > index 859668586..18d5efae0 100644
> > --- a/tests/atlocal.in
> > +++ b/tests/atlocal.in
> > @@ -2,6 +2,8 @@
> >  HAVE_OPENSSL='@HAVE_OPENSSL@'
> >  OPENSSL_SUPPORTS_SNI='@OPENSSL_SUPPORTS_SNI@'
> >  HAVE_UNBOUND='@HAVE_UNBOUND@'
> > +HAVE_BACKTRACE='@HAVE_BACKTRACE@'
> > +HAVE_UNWIND='@HAVE_UNWIND@'
> >  EGREP='@EGREP@'
> >  PYTHON3='@PYTHON3@'
> >  CFLAGS='@CFLAGS@'
> > diff --git a/tests/daemon.at b/tests/daemon.at
> > index d7981f9d2..bce54aa5b 100644
> > --- a/tests/daemon.at
> > +++ b/tests/daemon.at
> > @@ -234,3 +234,74 @@ OVS_WAIT_UNTIL([sc query ovsdb-server | grep STATE
> | grep STOPPED > /dev/null 2>
> >  AT_CHECK([sc delete ovsdb-server], [0], [[[SC]] DeleteService SUCCESS
> >  ])
> >  AT_CLEANUP
> > +
> > +
> > +AT_SETUP([backtrace --detach])
> > +AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" =
> "no"])
> > +
> > +# This test intentionally causes SIGSEGV, so make Address Sanitizer
> ignore it.
> > +ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
> > +
> > +# Skip it if UB Sanitizer is being used.  There's no way to disable the
> > +# SEGV check at runtime.
> > +AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
> > +
> > +# Start the daemon and make sure that the pidfile exists immediately.
> > +# We don't wait for the pidfile to get created because the daemon is
> > +# supposed to do so before the parent exits.
> > +AT_CHECK([ovsdb-server --detach --no-chdir --pidfile --no-db
> --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
> > +
> > +AT_CHECK([test -s ovsdb-server.pid])
> > +child=$(cat ovsdb-server.pid)
> > +
> > +OVS_WAIT_WHILE([kill -SEGV $child])
> > +OVS_WAIT_UNTIL([grep -q "^SIGSEGV detected, backtrace:"
> ovsdb-server.log])
> > +AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing
> dummy backtrace" ovsdb-server.log])
> > +
> > +AT_CLEANUP
> > +
> > +AT_SETUP([backtrace --detach --monitor])
> > +AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" =
> "no"])
> > +
> > +# This test intentionally causes SIGSEGV, so make Address Sanitizer
> ignore it.
> > +ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
> > +
> > +# Skip it if UB Sanitizer is being used.  There's no way to disable the
> > +# SEGV check at runtime.
> > +AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
> > +
> > +on_exit 'kill $(cat *.pid)'
> > +
> > +# Start the daemon and make sure that the pidfile exists immediately.
> > +# We don't wait for the pidfile to get created because the daemon is
> > +# supposed to do so before the parent exits.
> > +AT_CHECK([ovsdb-server --detach --monitor --no-chdir --pidfile --no-db
> --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
> > +AT_CHECK([test -s ovsdb-server.pid])
> > +child=$(cat ovsdb-server.pid)
> > +
> > +# Check process naming and ancestry.
> > +monitor=$(parent_pid $child)
> > +check_process_name $child ovsdb-server
> > +check_ancestors $child $monitor 1
> > +
> > +# Kill the daemon process, making it look like a segfault,
> > +# and wait for a new daemon process to get spawned.
> > +AT_CHECK([kill -SEGV $child], [0])
> > +OVS_WAIT_WHILE([kill -0 $child])
> > +OVS_WAIT_UNTIL([test -s ovsdb-server.pid && test `cat ovsdb-server.pid`
> != $child])
> > +child2=$(cat ovsdb-server.pid)
> > +
> > +# Check process naming and ancestry.
> > +check_process_name $child2 ovsdb-server
> > +check_ancestors $child2 $monitor 1
> > +
> > +# Kill the daemon process with SIGTERM, and wait for the daemon
> > +# and the monitor processes to go away and the pidfile to get deleted.
> > +AT_CHECK([kill $child2])
> > +OVS_WAIT_WHILE([kill -0 $monitor || kill -0 $child2 || test -e
> ovsdb-server.pid])
> > +
> > +AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing
> dummy backtrace" ovsdb-server.log])
> > +AT_CHECK([grep -q "^SIGSEGV detected, backtrace:" ovsdb-server.log])
> > +AT_CHECK([grep -q "daemon_unix(monitor)|ERR|1 crashes: pid .* died,
> killed (Segmentation fault), core dumped, restarting" ovsdb-server.log])
> > +
> > +AT_CLEANUP
>
>
Thanks,
Ales
Ilya Maximets March 23, 2023, 1:10 p.m. UTC | #3
On 3/23/23 07:14, Ales Musil wrote:
> 
> 
> On Wed, Mar 22, 2023 at 3:00 PM Aaron Conole <aconole@redhat.com <mailto:aconole@redhat.com>> wrote:
> 
>     Hi Ales,
> 
>  
> Hi Aaron,
> 
> 
>     Ales Musil <amusil@redhat.com <mailto:amusil@redhat.com>> writes:
> 
>     > Use the backtrace functions that is provided by libc,
>     > this allows us to get backtrace that is independent of
>     > the current memory map of the process. Which in turn can
>     > be used for debugging/tracing purpose. The backtrace
>     > is not 100% accurate due to various optimizations, most
>     > notably "-fomit-frame-pointer" and LTO. This might result
>     > that the line in source file doesn't correspond to the
>     > real line. However, it should be able to pinpoint at least
>     > the function where the backtrace was called.
>     >
>     > The usage for SIGSEGV is determined during compilation
>     > based on available libraries. Libunwind has higher priority
>     > if both methods are available to keep the compatibility with
>     > current behavior.
>     >
>     > The backtrace is not marked as signal safe however the backtrace
>     > manual page gives more detailed explanation why it might be the
>     > case [0]. Load the "libgcc" or equivalent in advance within the
>     > "fatal_signal_init" which should ensure that subsequent calls
>     > to backtrace* do not call malloc and are signal safe.
>     >
>     > The typical backtrace will look similar to the one below:
>     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
>     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
>     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
>     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d) [0x7fc5db563a8d]
>     > ovsdb-server(+0xa661) [0x562cfce2e661]
>     > ovsdb-server(+0x7e39) [0x562cfce2be39]
>     > /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
>     > /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
>     > ovsdb-server(+0x8c35) [0x562cfce2cc35]
>     >
>     > backtrace.h elaborates on how to effectively get the line
>     > information associated with the addressed presented in the
>     > backtrace.
>     >
>     > [0]
>     > backtrace() and backtrace_symbols_fd() don't call malloc()
>     > explicitly, but they are part of libgcc, which gets loaded
>     > dynamically when first used.  Dynamic loading usually triggers
>     > a call to malloc(3).  If you need certain calls to these two
>     > functions to not allocate memory (in signal handlers, for
>     > example), you need to make sure libgcc is loaded beforehand
>     >
>     > Reported-at: https://bugzilla.redhat.com/2177760 <https://bugzilla.redhat.com/2177760>
>     > Signed-off-by: Ales Musil <amusil@redhat.com <mailto:amusil@redhat.com>>
>     > ---
>     > v2: Extend the current use of libunwind rather than replacing it.
> 
>     Thanks for this.  Sorry for the quick review here - I've not gotten a
>     chance to get too in-depth.  Comments below.
> 
> 
> Thanks for the feedback, please see the reply below.
>  
> 
> 
>     > ---
>     >  include/openvswitch/vlog.h |   4 +-
>     >  lib/backtrace.c            |  77 +++++++++-------------------
>     >  lib/backtrace.h            |  58 ++++++++++++---------
>     >  lib/daemon-unix.c          |   1 -
>     >  lib/fatal-signal.c         | 102 ++++++++++++++++++++++---------------
>     >  lib/ovsdb-error.c          |  15 ++----
>     >  lib/vlog.c                 |  14 ++---
>     >  m4/openvswitch.m4          |   9 ++--
>     >  tests/atlocal.in <http://atlocal.in>           |   2 +
>     >  tests/daemon.at <http://daemon.at>            |  71 ++++++++++++++++++++++++++
>     >  10 files changed, 208 insertions(+), 145 deletions(-)

<snip>

>     >          return;
>     >      }
>     > 
>     > @@ -204,44 +212,58 @@ send_backtrace_to_monitor(void) {
>     >          dep++;
>     >      }
>     > 
>     > -    if (monitor) {
> 
>     Hrrm.. did we lose the ability to send the backtrace back to the monitor
>     with this patchset?  It looks like now the daemon that is failing to
>     segv direct writes the data to the logfile, did I get it right?  If so,
>     why change this behavior?
> 
> 
> 
> Unless I'm missing something we don't need it. AFAIU the log file is the same for both
> daemon and the monitor. So we can actually do the operation directly without the need
> to send it to monitor with the same result.

I think, we need to send to the monitor.  We're in the signal context here
and, even worse, the SIGSEGV context.  Chances are, this process is messed up.
Even under normal conditions disk writes are tricky and there is no guarantee
that successful write() call actually results in data being written.
Here, in the signal handler, we do not re-try or even check the result.  And
we're definitely not syncing the file system before re-rising the signal.
This write() call is just a last resort when we can't really do anything else,
and we just hope that some of that data will appear in the log file.  It may
also end up in the middle of some other log messages that we're asynchronously
requested form other threads before the crash happened.

With writing from the monitor we have a proper logging with all the error
handling that will make sure that data wasn't lost.  And we're writing a much
smaller chunk of data to a much more reliable pipe from the signal handler,
increasing our chances for success.

Best regards, Ilya Maximets.
Ales Musil March 23, 2023, 1:19 p.m. UTC | #4
On Thu, Mar 23, 2023 at 2:09 PM Ilya Maximets <i.maximets@ovn.org> wrote:

> On 3/23/23 07:14, Ales Musil wrote:
> >
> >
> > On Wed, Mar 22, 2023 at 3:00 PM Aaron Conole <aconole@redhat.com
> <mailto:aconole@redhat.com>> wrote:
> >
> >     Hi Ales,
> >
> >
> > Hi Aaron,
> >
> >
> >     Ales Musil <amusil@redhat.com <mailto:amusil@redhat.com>> writes:
> >
> >     > Use the backtrace functions that is provided by libc,
> >     > this allows us to get backtrace that is independent of
> >     > the current memory map of the process. Which in turn can
> >     > be used for debugging/tracing purpose. The backtrace
> >     > is not 100% accurate due to various optimizations, most
> >     > notably "-fomit-frame-pointer" and LTO. This might result
> >     > that the line in source file doesn't correspond to the
> >     > real line. However, it should be able to pinpoint at least
> >     > the function where the backtrace was called.
> >     >
> >     > The usage for SIGSEGV is determined during compilation
> >     > based on available libraries. Libunwind has higher priority
> >     > if both methods are available to keep the compatibility with
> >     > current behavior.
> >     >
> >     > The backtrace is not marked as signal safe however the backtrace
> >     > manual page gives more detailed explanation why it might be the
> >     > case [0]. Load the "libgcc" or equivalent in advance within the
> >     > "fatal_signal_init" which should ensure that subsequent calls
> >     > to backtrace* do not call malloc and are signal safe.
> >     >
> >     > The typical backtrace will look similar to the one below:
> >     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>.0(backtrace_capture+0x1e)
> [0x7fc5db298dfe]
> >     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>.0(log_backtrace_at+0x57)
> [0x7fc5db2999e7]
> >     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
> >     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d)
> [0x7fc5db563a8d]
> >     > ovsdb-server(+0xa661) [0x562cfce2e661]
> >     > ovsdb-server(+0x7e39) [0x562cfce2be39]
> >     > /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
> >     > /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
> >     > ovsdb-server(+0x8c35) [0x562cfce2cc35]
> >     >
> >     > backtrace.h elaborates on how to effectively get the line
> >     > information associated with the addressed presented in the
> >     > backtrace.
> >     >
> >     > [0]
> >     > backtrace() and backtrace_symbols_fd() don't call malloc()
> >     > explicitly, but they are part of libgcc, which gets loaded
> >     > dynamically when first used.  Dynamic loading usually triggers
> >     > a call to malloc(3).  If you need certain calls to these two
> >     > functions to not allocate memory (in signal handlers, for
> >     > example), you need to make sure libgcc is loaded beforehand
> >     >
> >     > Reported-at: https://bugzilla.redhat.com/2177760 <
> https://bugzilla.redhat.com/2177760>
> >     > Signed-off-by: Ales Musil <amusil@redhat.com <mailto:
> amusil@redhat.com>>
> >     > ---
> >     > v2: Extend the current use of libunwind rather than replacing it.
> >
> >     Thanks for this.  Sorry for the quick review here - I've not gotten a
> >     chance to get too in-depth.  Comments below.
> >
> >
> > Thanks for the feedback, please see the reply below.
> >
> >
> >
> >     > ---
> >     >  include/openvswitch/vlog.h |   4 +-
> >     >  lib/backtrace.c            |  77 +++++++++-------------------
> >     >  lib/backtrace.h            |  58 ++++++++++++---------
> >     >  lib/daemon-unix.c          |   1 -
> >     >  lib/fatal-signal.c         | 102
> ++++++++++++++++++++++---------------
> >     >  lib/ovsdb-error.c          |  15 ++----
> >     >  lib/vlog.c                 |  14 ++---
> >     >  m4/openvswitch.m4          |   9 ++--
> >     >  tests/atlocal.in <http://atlocal.in>           |   2 +
> >     >  tests/daemon.at <http://daemon.at>            |  71
> ++++++++++++++++++++++++++
> >     >  10 files changed, 208 insertions(+), 145 deletions(-)
>
> <snip>
>
> >     >          return;
> >     >      }
> >     >
> >     > @@ -204,44 +212,58 @@ send_backtrace_to_monitor(void) {
> >     >          dep++;
> >     >      }
> >     >
> >     > -    if (monitor) {
> >
> >     Hrrm.. did we lose the ability to send the backtrace back to the
> monitor
> >     with this patchset?  It looks like now the daemon that is failing to
> >     segv direct writes the data to the logfile, did I get it right?  If
> so,
> >     why change this behavior?
> >
> >
> >
> > Unless I'm missing something we don't need it. AFAIU the log file is the
> same for both
> > daemon and the monitor. So we can actually do the operation directly
> without the need
> > to send it to monitor with the same result.
>
> I think, we need to send to the monitor.  We're in the signal context here
> and, even worse, the SIGSEGV context.  Chances are, this process is messed
> up.
> Even under normal conditions disk writes are tricky and there is no
> guarantee
> that successful write() call actually results in data being written.
> Here, in the signal handler, we do not re-try or even check the result.
> And
> we're definitely not syncing the file system before re-rising the signal.
> This write() call is just a last resort when we can't really do anything
> else,
> and we just hope that some of that data will appear in the log file.  It
> may
> also end up in the middle of some other log messages that we're
> asynchronously
> requested form other threads before the crash happened.
>
> With writing from the monitor we have a proper logging with all the error
> handling that will make sure that data wasn't lost.  And we're writing a
> much
> smaller chunk of data to a much more reliable pipe from the signal handler,
> increasing our chances for success.
>
> Best regards, Ilya Maximets.
>
>
That makes sense, there is a catch, we need to have a common format
(string?) for both
libunwind and backtrace or something that would differentiate them for the
logging
inside monitor. Because the libunwind currently relies on the fact that it
gets decoded
in the monitor, but backtrace_monitor_fd will send it as a sequence of
strings.

Thanks.
Ales
Ilya Maximets March 23, 2023, 1:24 p.m. UTC | #5
On 3/23/23 14:19, Ales Musil wrote:
> 
> 
> On Thu, Mar 23, 2023 at 2:09 PM Ilya Maximets <i.maximets@ovn.org <mailto:i.maximets@ovn.org>> wrote:
> 
>     On 3/23/23 07:14, Ales Musil wrote:
>     >
>     >
>     > On Wed, Mar 22, 2023 at 3:00 PM Aaron Conole <aconole@redhat.com <mailto:aconole@redhat.com> <mailto:aconole@redhat.com <mailto:aconole@redhat.com>>> wrote:
>     >
>     >     Hi Ales,
>     >
>     >  
>     > Hi Aaron,
>     >
>     >
>     >     Ales Musil <amusil@redhat.com <mailto:amusil@redhat.com> <mailto:amusil@redhat.com <mailto:amusil@redhat.com>>> writes:
>     >
>     >     > Use the backtrace functions that is provided by libc,
>     >     > this allows us to get backtrace that is independent of
>     >     > the current memory map of the process. Which in turn can
>     >     > be used for debugging/tracing purpose. The backtrace
>     >     > is not 100% accurate due to various optimizations, most
>     >     > notably "-fomit-frame-pointer" and LTO. This might result
>     >     > that the line in source file doesn't correspond to the
>     >     > real line. However, it should be able to pinpoint at least
>     >     > the function where the backtrace was called.
>     >     >
>     >     > The usage for SIGSEGV is determined during compilation
>     >     > based on available libraries. Libunwind has higher priority
>     >     > if both methods are available to keep the compatibility with
>     >     > current behavior.
>     >     >
>     >     > The backtrace is not marked as signal safe however the backtrace
>     >     > manual page gives more detailed explanation why it might be the
>     >     > case [0]. Load the "libgcc" or equivalent in advance within the
>     >     > "fatal_signal_init" which should ensure that subsequent calls
>     >     > to backtrace* do not call malloc and are signal safe.
>     >     >
>     >     > The typical backtrace will look similar to the one below:
>     >     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so> <http://libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>>.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
>     >     > /lib64/libopenvswitch-3.1.so <http://libopenvswitch-3.1.so> <http://libopenvswitch-3.1.so <http://libopenvswitch-3.1.so>>.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
>     >     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
>     >     > /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d) [0x7fc5db563a8d]
>     >     > ovsdb-server(+0xa661) [0x562cfce2e661]
>     >     > ovsdb-server(+0x7e39) [0x562cfce2be39]
>     >     > /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
>     >     > /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
>     >     > ovsdb-server(+0x8c35) [0x562cfce2cc35]
>     >     >
>     >     > backtrace.h elaborates on how to effectively get the line
>     >     > information associated with the addressed presented in the
>     >     > backtrace.
>     >     >
>     >     > [0]
>     >     > backtrace() and backtrace_symbols_fd() don't call malloc()
>     >     > explicitly, but they are part of libgcc, which gets loaded
>     >     > dynamically when first used.  Dynamic loading usually triggers
>     >     > a call to malloc(3).  If you need certain calls to these two
>     >     > functions to not allocate memory (in signal handlers, for
>     >     > example), you need to make sure libgcc is loaded beforehand
>     >     >
>     >     > Reported-at: https://bugzilla.redhat.com/2177760 <https://bugzilla.redhat.com/2177760> <https://bugzilla.redhat.com/2177760 <https://bugzilla.redhat.com/2177760>>
>     >     > Signed-off-by: Ales Musil <amusil@redhat.com <mailto:amusil@redhat.com> <mailto:amusil@redhat.com <mailto:amusil@redhat.com>>>
>     >     > ---
>     >     > v2: Extend the current use of libunwind rather than replacing it.
>     >
>     >     Thanks for this.  Sorry for the quick review here - I've not gotten a
>     >     chance to get too in-depth.  Comments below.
>     >
>     >
>     > Thanks for the feedback, please see the reply below.
>     >  
>     >
>     >
>     >     > ---
>     >     >  include/openvswitch/vlog.h |   4 +-
>     >     >  lib/backtrace.c            |  77 +++++++++-------------------
>     >     >  lib/backtrace.h            |  58 ++++++++++++---------
>     >     >  lib/daemon-unix.c          |   1 -
>     >     >  lib/fatal-signal.c         | 102 ++++++++++++++++++++++---------------
>     >     >  lib/ovsdb-error.c          |  15 ++----
>     >     >  lib/vlog.c                 |  14 ++---
>     >     >  m4/openvswitch.m4          |   9 ++--
>     >     >  tests/atlocal.in <http://atlocal.in> <http://atlocal.in <http://atlocal.in>>           |   2 +
>     >     >  tests/daemon.at <http://daemon.at> <http://daemon.at <http://daemon.at>>            |  71 ++++++++++++++++++++++++++
>     >     >  10 files changed, 208 insertions(+), 145 deletions(-)
> 
>     <snip>
> 
>     >     >          return;
>     >     >      }
>     >     > 
>     >     > @@ -204,44 +212,58 @@ send_backtrace_to_monitor(void) {
>     >     >          dep++;
>     >     >      }
>     >     > 
>     >     > -    if (monitor) {
>     >
>     >     Hrrm.. did we lose the ability to send the backtrace back to the monitor
>     >     with this patchset?  It looks like now the daemon that is failing to
>     >     segv direct writes the data to the logfile, did I get it right?  If so,
>     >     why change this behavior?
>     >
>     >
>     >
>     > Unless I'm missing something we don't need it. AFAIU the log file is the same for both
>     > daemon and the monitor. So we can actually do the operation directly without the need
>     > to send it to monitor with the same result.
> 
>     I think, we need to send to the monitor.  We're in the signal context here
>     and, even worse, the SIGSEGV context.  Chances are, this process is messed up.
>     Even under normal conditions disk writes are tricky and there is no guarantee
>     that successful write() call actually results in data being written.
>     Here, in the signal handler, we do not re-try or even check the result.  And
>     we're definitely not syncing the file system before re-rising the signal.
>     This write() call is just a last resort when we can't really do anything else,
>     and we just hope that some of that data will appear in the log file.  It may
>     also end up in the middle of some other log messages that we're asynchronously
>     requested form other threads before the crash happened.
> 
>     With writing from the monitor we have a proper logging with all the error
>     handling that will make sure that data wasn't lost.  And we're writing a much
>     smaller chunk of data to a much more reliable pipe from the signal handler,
>     increasing our chances for success.
> 
>     Best regards, Ilya Maximets.
> 
> 
> That makes sense, there is a catch, we need to have a common format (string?) for both
> libunwind and backtrace or something that would differentiate them for the logging
> inside monitor. Because the libunwind currently relies on the fact that it gets decoded
> in the monitor, but backtrace_monitor_fd will send it as a sequence of strings.

Monitor and the main deamon are the same binary.
Compile-time checking, i.e. conditional compiling, is fine.

> 
> Thanks.
> Ales
> 
> -- 
> 
> Ales Musil
> 
> Senior Software Engineer - OVN Core
> 
> Red Hat EMEA <https://www.redhat.com>
> 
> amusil@redhat.com <mailto:amusil@redhat.com>    IM: amusil
> 
> <https://red.ht/sig>
>
diff mbox series

Patch

diff --git a/include/openvswitch/vlog.h b/include/openvswitch/vlog.h
index e53ce6d81..98edc3452 100644
--- a/include/openvswitch/vlog.h
+++ b/include/openvswitch/vlog.h
@@ -145,8 +145,8 @@  void vlog_set_syslog_method(const char *method);
 /* Configure syslog target. */
 void vlog_set_syslog_target(const char *target);
 
-/* Write directly to log file. */
-void vlog_direct_write_to_log_file_unsafe(const char *s);
+/* Return the current vlog file descriptor. */
+int vlog_fd(void);
 
 /* Initialization. */
 void vlog_init(void);
diff --git a/lib/backtrace.c b/lib/backtrace.c
index 2853d5ff1..69e1281b0 100644
--- a/lib/backtrace.c
+++ b/lib/backtrace.c
@@ -32,12 +32,23 @@  VLOG_DEFINE_THIS_MODULE(backtrace);
 void
 backtrace_capture(struct backtrace *b)
 {
-    void *frames[BACKTRACE_MAX_FRAMES];
-    int i;
+    b->n_frames = backtrace(b->frames, BACKTRACE_MAX_FRAMES);
+}
+
+void
+backtrace_format(const struct backtrace *bt, struct ds *ds)
+{
+    if (bt->n_frames) {
+        char **symbols = backtrace_symbols(bt->frames, bt->n_frames);
+        if (!symbols) {
+            return;
+        }
+
+        for (int i = 0; i < bt->n_frames; i++) {
+            ds_put_format(ds, "%s\n", symbols[i]);
+        }
 
-    b->n_frames = backtrace(frames, BACKTRACE_MAX_FRAMES);
-    for (i = 0; i < b->n_frames; i++) {
-        b->frames[i] = (uintptr_t) frames[i];
+        free(symbols);
     }
 }
 
@@ -47,23 +58,13 @@  backtrace_capture(struct backtrace *backtrace)
 {
     backtrace->n_frames = 0;
 }
-#endif
 
-static char *
-backtrace_format(const struct backtrace *b, struct ds *ds)
+void
+backtrace_format(const struct backtrace *bt OVS_UNUSED, struct ds *ds)
 {
-    if (b->n_frames) {
-        int i;
-
-        ds_put_cstr(ds, " (backtrace:");
-        for (i = 0; i < b->n_frames; i++) {
-            ds_put_format(ds, " 0x%08"PRIxPTR, b->frames[i]);
-        }
-        ds_put_cstr(ds, ")");
-    }
-
-    return ds_cstr(ds);
+    ds_put_cstr(ds, "backtrace() is not supported!\n");
 }
+#endif
 
 void
 log_backtrace_at(const char *msg, const char *where)
@@ -77,41 +78,9 @@  log_backtrace_at(const char *msg, const char *where)
     }
 
     ds_put_cstr(&ds, where);
-    VLOG_ERR("%s", backtrace_format(&b, &ds));
+    ds_put_cstr(&ds, " backtrace:\n");
+    backtrace_format(&b, &ds);
+    VLOG_ERR("%s", ds_cstr_ro(&ds));
 
     ds_destroy(&ds);
 }
-
-#ifdef HAVE_UNWIND
-void
-log_received_backtrace(int fd) {
-    int byte_read;
-    struct unw_backtrace backtrace[UNW_MAX_DEPTH];
-
-    VLOG_WARN("%s fd %d", __func__, fd);
-    fcntl(fd, F_SETFL, O_NONBLOCK);
-    memset(backtrace, 0, UNW_MAX_BUF);
-
-    byte_read = read(fd, backtrace, UNW_MAX_BUF);
-    if (byte_read < 0) {
-        VLOG_ERR("Read fd %d failed: %s", fd,
-                 ovs_strerror(errno));
-    } else if (byte_read > 0) {
-        VLOG_WARN("SIGSEGV detected, backtrace:");
-        for (int i = 0; i < UNW_MAX_DEPTH; i++) {
-            if (backtrace[i].func[0] == 0) {
-                break;
-            }
-            VLOG_WARN("0x%016"PRIxPTR" <%s+0x%"PRIxPTR">\n",
-                      backtrace[i].ip,
-                      backtrace[i].func,
-                      backtrace[i].offset);
-        }
-    }
-}
-#else /* !HAVE_UNWIND */
-void
-log_received_backtrace(int daemonize_fd OVS_UNUSED) {
-    VLOG_WARN("Backtrace using libunwind not supported.");
-}
-#endif /* HAVE_UNWIND */
diff --git a/lib/backtrace.h b/lib/backtrace.h
index 5708bf9c6..ecb3c464c 100644
--- a/lib/backtrace.h
+++ b/lib/backtrace.h
@@ -36,41 +36,53 @@ 
  *       log_backtrace_msg("your message");         <-- with a message
  *
  *
- * A typical log will look like the following. The hex numbers listed after
- * "backtrace" are the addresses of the backtrace.
+ * A typical backtrace will look like the following example:
+ * /lib64/libopenvswitch-3.1.so.0(backtrace_capture+0x1e) [0x7fc5db298dfe]
+ * /lib64/libopenvswitch-3.1.so.0(log_backtrace_at+0x57) [0x7fc5db2999e7]
+ * /lib64/libovsdb-3.1.so.0(ovsdb_txn_complete+0x7b) [0x7fc5db56247b]
+ * /lib64/libovsdb-3.1.so.0(ovsdb_txn_propose_commit_block+0x8d)
+ * [0x7fc5db563a8d]
+ * ovsdb-server(+0xa661) [0x562cfce2e661]
+ * ovsdb-server(+0x7e39) [0x562cfce2be39]
+ * /lib64/libc.so.6(+0x27b4a) [0x7fc5db048b4a]
+ * /lib64/libc.so.6(__libc_start_main+0x8b) [0x7fc5db048c0b]
+ * ovsdb-server(+0x8c35) [0x562cfce2cc35]
  *
- * 2014-03-13T23:18:11.979Z|00002|backtrace(revalidator_6)|ERR|lib/dpif-netdev.c:1312: (backtrace: 0x00521f57 0x00460365 0x00463ea4 0x0046470b 0x0043b32d 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3 0x2b5b3ac94e9a 0x2b5b3b4a33fd)
+ * GDB can be used to view the exact line of the code for particular backtrace.
+ * One thing to keep in mind is that the lines in source files might not
+ * 100% correspond with the backtrace due to various optimizations as LTO etc.
+ * (The effect can be seen in this example).
  *
- * The following bash command can be used to  view backtrace in
- * a more readable form.
- * addr2line -p -e vswitchd/ovs-vswitchd <cut-and-paste back traces>
+ * Assuming that debuginfo for the library or binary is installed load it to
+ * GDB:
+ * $ gdb ovsdb-server
+ * (gdb) list *(+0x7e39)
+ * 0x7e39 is in main (ovsdb/ovsdb-server.c:278).
+ * (gdb) list *(+0xa661)
+ * 0xa661 is in commit_txn (ovsdb/ovsdb-server.c:1173)
  *
- * An typical run and output will look like:
- * addr2line -p -e vswitchd/ovs-vswitchd  0x00521f57 0x00460365 0x00463ea4
- * 0x0046470b 0x0043b32d 0x0043bac3 0x0043bae2 0x0043943b 0x004c22b3
- * 0x2b5b3ac94e9a 0x2b5b3b4a33fd
+ * $ gdb /lib64/libovsdb-3.1.so.0
+ * (gdb) list *(ovsdb_txn_propose_commit_block+0x8d)
+ * 0x3aa8d is in ovsdb_txn_propose_commit_block (ovsdb/transaction.c:1328)
+ * (gdb) list *(ovsdb_txn_complete+0x7b)
+ * 0x3947b is in ovsdb_txn_complete (./include/openvswitch/list.h:321)
  *
- * openvswitch/lib/backtrace.c:33
- * openvswitch/lib/dpif-netdev.c:1312
- * openvswitch/lib/dpif.c:937
- * openvswitch/lib/dpif.c:1258
- * openvswitch/ofproto/ofproto-dpif-upcall.c:1440
- * openvswitch/ofproto/ofproto-dpif-upcall.c:1595
- * openvswitch/ofproto/ofproto-dpif-upcall.c:160
- * openvswitch/ofproto/ofproto-dpif-upcall.c:717
- * openvswitch/lib/ovs-thread.c:268
- * ??:0
- * ??:0
+ * $ gdb /lib64/libopenvswitch-3.1.so.0
+ * (gdb) list *(log_backtrace_at+0x57)
+ * 0x999e7 is in log_backtrace_at (lib/backtrace.c:77)
+ * (gdb) list *(backtrace_capture+0x1e)
+ * 0x98dfe is in backtrace_capture (lib/backtrace.c:35)
  */
 
 #define log_backtrace() log_backtrace_at(NULL, OVS_SOURCE_LOCATOR);
 #define log_backtrace_msg(msg) log_backtrace_at(msg, OVS_SOURCE_LOCATOR);
 
 #define BACKTRACE_MAX_FRAMES 31
+#define BACKTRACE_DUMP_MSG "SIGSEGV detected, backtrace:\n"
 
 struct backtrace {
     int n_frames;
-    uintptr_t frames[BACKTRACE_MAX_FRAMES];
+    void *frames[BACKTRACE_MAX_FRAMES];
 };
 
 #ifdef HAVE_UNWIND
@@ -88,6 +100,6 @@  struct unw_backtrace {
 
 void backtrace_capture(struct backtrace *);
 void log_backtrace_at(const char *msg, const char *where);
-void log_received_backtrace(int fd);
+void backtrace_format(const struct backtrace *bt, struct ds *ds);
 
 #endif /* backtrace.h */
diff --git a/lib/daemon-unix.c b/lib/daemon-unix.c
index 1a7ba427d..68706f73a 100644
--- a/lib/daemon-unix.c
+++ b/lib/daemon-unix.c
@@ -395,7 +395,6 @@  monitor_daemon(pid_t daemon_pid)
                     }
                 }
 
-                log_received_backtrace(daemonize_fd);
                 close(daemonize_fd);
                 daemonize_fd = -1;
 
diff --git a/lib/fatal-signal.c b/lib/fatal-signal.c
index bbb31ef27..07b088f69 100644
--- a/lib/fatal-signal.c
+++ b/lib/fatal-signal.c
@@ -35,8 +35,8 @@ 
 
 #include "openvswitch/type-props.h"
 
-#ifdef HAVE_UNWIND
-#include "daemon-private.h"
+#ifdef HAVE_BACKTRACE
+#include <execinfo.h>
 #endif
 
 #ifndef SIG_ATOMIC_MAX
@@ -94,6 +94,13 @@  fatal_signal_init(void)
         inited = true;
 
         ovs_mutex_init_recursive(&mutex);
+
+        /* The dummy backtrace is needed see comment for
+         * send_backtrace_to_monitor(). */
+        struct backtrace dummy_bt;
+        backtrace_capture(&dummy_bt);
+        VLOG_DBG("Load needed libraries by capturing dummy backtrace,"
+                 " n_frames=%d", dummy_bt.n_frames);
 #ifndef _WIN32
         xpipe_nonblocking(signal_fds);
 #else
@@ -175,20 +182,21 @@  llong_to_hex_str(unsigned long long value, char *str)
     return i + 1;
 }
 
-/* Send the backtrace buffer to monitor thread.
+/* Print backtrace.
  *
  * Note that this runs in the signal handling context, any system
  * library functions used here must be async-signal-safe.
  */
 static inline void
-send_backtrace_to_monitor(void) {
+print_backtrace(void) {
     /* volatile added to prevent a "clobbered" error on ppc64le with gcc */
     volatile int dep;
     struct unw_backtrace unw_bt[UNW_MAX_DEPTH];
     unw_cursor_t cursor;
     unw_context_t uc;
 
-    if (daemonize_fd == -1) {
+    int log_fd = vlog_fd();
+    if (!log_fd) {
         return;
     }
 
@@ -204,44 +212,58 @@  send_backtrace_to_monitor(void) {
         dep++;
     }
 
-    if (monitor) {
-        ignore(write(daemonize_fd, unw_bt,
-                     dep * sizeof(struct unw_backtrace)));
-    } else {
-        /* Since there is no monitor daemon running, write backtrace
-         * in current process.
-         */
-        char str[] = "SIGSEGV detected, backtrace:\n";
-        char ip_str[16], offset_str[6];
-        char line[64], fn_name[UNW_MAX_FUNCN];
-
-        vlog_direct_write_to_log_file_unsafe(str);
-
-        for (int i = 0; i < dep; i++) {
-            memset(line, 0, sizeof line);
-            memset(fn_name, 0, sizeof fn_name);
-            memset(offset_str, 0, sizeof offset_str);
-            memset(ip_str, ' ', sizeof ip_str);
-            ip_str[sizeof(ip_str) - 1] = 0;
-
-            llong_to_hex_str(unw_bt[i].ip, ip_str);
-            llong_to_hex_str(unw_bt[i].offset, offset_str);
-
-            strcat(line, "0x");
-            strcat(line, ip_str);
-            strcat(line, "<");
-            memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
-            strcat(line, fn_name);
-            strcat(line, "+0x");
-            strcat(line, offset_str);
-            strcat(line, ">\n");
-            vlog_direct_write_to_log_file_unsafe(line);
-        }
+    char ip_str[16], offset_str[6];
+    char line[64], fn_name[UNW_MAX_FUNCN];
+
+    ignore(write(log_fd, BACKTRACE_DUMP_MSG, strlen(BACKTRACE_DUMP_MSG)));
+
+    for (int i = 0; i < dep; i++) {
+        memset(line, 0, sizeof line);
+        memset(fn_name, 0, sizeof fn_name);
+        memset(offset_str, 0, sizeof offset_str);
+        memset(ip_str, ' ', sizeof ip_str);
+        ip_str[sizeof(ip_str) - 1] = 0;
+
+        llong_to_hex_str(unw_bt[i].ip, ip_str);
+        llong_to_hex_str(unw_bt[i].offset, offset_str);
+
+        strcat(line, "0x");
+        strcat(line, ip_str);
+        strcat(line, "<");
+        memcpy(fn_name, unw_bt[i].func, UNW_MAX_FUNCN - 1);
+        strcat(line, fn_name);
+        strcat(line, "+0x");
+        strcat(line, offset_str);
+        strcat(line, ">\n");
+        ignore(write(log_fd, line, strlen(line)));
     }
 }
+#elif HAVE_BACKTRACE
+/* Print backtrace.
+ *
+ * Note that this runs in the signal handling context, any system
+ * library functions used here must be async-signal-safe.
+ * backtrace() is only signal safe if the "libgcc" or equivalent was loaded
+ * before the signal handler. In order to keep it safe the fatal_signal_init()
+ * should always call backtrace_capture which will ensure that "libgcc" or
+ * equivlent is loaded.
+ */
+static inline void
+print_backtrace(void) {
+    int log_fd = vlog_fd();
+    if (!log_fd) {
+        return;
+    }
+
+    struct backtrace bt;
+    backtrace_capture(&bt);
+
+    ignore(write(log_fd, BACKTRACE_DUMP_MSG, strlen(BACKTRACE_DUMP_MSG)));
+    backtrace_symbols_fd(bt.frames, bt.n_frames, log_fd);
+}
 #else
 static inline void
-send_backtrace_to_monitor(void) {
+print_backtrace(void) {
     /* Nothing. */
 }
 #endif
@@ -261,7 +283,7 @@  fatal_signal_handler(int sig_nr)
 #ifndef _WIN32
     if (sig_nr == SIGSEGV) {
         signal(sig_nr, SIG_DFL); /* Set it back immediately. */
-        send_backtrace_to_monitor();
+        print_backtrace();
         raise(sig_nr);
     }
     ignore(write(signal_fds[1], "", 1));
diff --git a/lib/ovsdb-error.c b/lib/ovsdb-error.c
index a75ad36b7..2cd6242f3 100644
--- a/lib/ovsdb-error.c
+++ b/lib/ovsdb-error.c
@@ -139,17 +139,6 @@  ovsdb_internal_error(struct ovsdb_error *inner_error,
         va_end(args);
     }
 
-    backtrace_capture(&backtrace);
-    if (backtrace.n_frames) {
-        int i;
-
-        ds_put_cstr(&ds, " (backtrace:");
-        for (i = 0; i < backtrace.n_frames; i++) {
-            ds_put_format(&ds, " 0x%08"PRIxPTR, backtrace.frames[i]);
-        }
-        ds_put_char(&ds, ')');
-    }
-
     ds_put_format(&ds, " (%s %s)", program_name, VERSION);
 
     if (inner_error) {
@@ -158,6 +147,10 @@  ovsdb_internal_error(struct ovsdb_error *inner_error,
         free(s);
     }
 
+    ds_put_cstr(&ds, ", backtrace:");
+    backtrace_capture(&backtrace);
+    backtrace_format(&backtrace, &ds);
+
     error = ovsdb_error("internal error", "%s", ds_cstr(&ds));
 
     ds_destroy(&ds);
diff --git a/lib/vlog.c b/lib/vlog.c
index 9ddea48b8..b40c6909d 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -649,19 +649,11 @@  vlog_set_syslog_target(const char *target)
     ovs_rwlock_unlock(&pattern_rwlock);
 }
 
-/*
- * This function writes directly to log file without using async writer or
- * taking a lock.  Caller must hold 'log_file_mutex' or be sure that it's
- * not necessary.  Could be used in exceptional cases like dumping of backtrace
- * on fatal signals.
- */
-void
-vlog_direct_write_to_log_file_unsafe(const char *s)
+int
+vlog_fd(void)
     OVS_NO_THREAD_SAFETY_ANALYSIS
 {
-    if (log_fd >= 0) {
-        ignore(write(log_fd, s, strlen(s)));
-    }
+    return log_fd;
 }
 
 /* Returns 'false' if 'facility' is not a valid string. If 'facility'
diff --git a/m4/openvswitch.m4 b/m4/openvswitch.m4
index 14d9249b8..f4943b140 100644
--- a/m4/openvswitch.m4
+++ b/m4/openvswitch.m4
@@ -359,9 +359,12 @@  AC_DEFUN([OVS_CHECK_DBDIR],
 
 dnl Defines HAVE_BACKTRACE if backtrace() is found.
 AC_DEFUN([OVS_CHECK_BACKTRACE],
-  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace],
-                  [AC_DEFINE([HAVE_BACKTRACE], [1],
-                             [Define to 1 if you have backtrace(3).])])])
+  [AC_SEARCH_LIBS([backtrace], [execinfo ubacktrace], [HAVE_BACKTRACE=yes], [HAVE_BACKTRACE=no])
+   if test "$HAVE_BACKTRACE" = "yes"; then
+     AC_DEFINE([HAVE_BACKTRACE], [1], [Define to 1 if you have backtrace(3).])
+   fi
+   AM_CONDITIONAL([HAVE_BACKTRACE], [test "$HAVE_BACKTRACE" = "yes"])
+   AC_SUBST([HAVE_BACKTRACE])])
 
 dnl Defines HAVE_PERF_EVENT if linux/perf_event.h is found.
 AC_DEFUN([OVS_CHECK_PERF_EVENT],
diff --git a/tests/atlocal.in b/tests/atlocal.in
index 859668586..18d5efae0 100644
--- a/tests/atlocal.in
+++ b/tests/atlocal.in
@@ -2,6 +2,8 @@ 
 HAVE_OPENSSL='@HAVE_OPENSSL@'
 OPENSSL_SUPPORTS_SNI='@OPENSSL_SUPPORTS_SNI@'
 HAVE_UNBOUND='@HAVE_UNBOUND@'
+HAVE_BACKTRACE='@HAVE_BACKTRACE@'
+HAVE_UNWIND='@HAVE_UNWIND@'
 EGREP='@EGREP@'
 PYTHON3='@PYTHON3@'
 CFLAGS='@CFLAGS@'
diff --git a/tests/daemon.at b/tests/daemon.at
index d7981f9d2..bce54aa5b 100644
--- a/tests/daemon.at
+++ b/tests/daemon.at
@@ -234,3 +234,74 @@  OVS_WAIT_UNTIL([sc query ovsdb-server | grep STATE | grep STOPPED > /dev/null 2>
 AT_CHECK([sc delete ovsdb-server], [0], [[[SC]] DeleteService SUCCESS
 ])
 AT_CLEANUP
+
+
+AT_SETUP([backtrace --detach])
+AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" = "no"])
+
+# This test intentionally causes SIGSEGV, so make Address Sanitizer ignore it.
+ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
+
+# Skip it if UB Sanitizer is being used.  There's no way to disable the
+# SEGV check at runtime.
+AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
+
+# Start the daemon and make sure that the pidfile exists immediately.
+# We don't wait for the pidfile to get created because the daemon is
+# supposed to do so before the parent exits.
+AT_CHECK([ovsdb-server --detach --no-chdir --pidfile --no-db --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
+
+AT_CHECK([test -s ovsdb-server.pid])
+child=$(cat ovsdb-server.pid)
+
+OVS_WAIT_WHILE([kill -SEGV $child])
+OVS_WAIT_UNTIL([grep -q "^SIGSEGV detected, backtrace:" ovsdb-server.log])
+AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing dummy backtrace" ovsdb-server.log])
+
+AT_CLEANUP
+
+AT_SETUP([backtrace --detach --monitor])
+AT_SKIP_IF([test "$HAVE_BACKTRACE" = "no" && test "$HAVE_UNWIND" = "no"])
+
+# This test intentionally causes SIGSEGV, so make Address Sanitizer ignore it.
+ASAN_OPTIONS=$ASAN_OPTIONS:handle_segv=0; export ASAN_OPTIONS
+
+# Skip it if UB Sanitizer is being used.  There's no way to disable the
+# SEGV check at runtime.
+AT_SKIP_IF([test $TESTS_WITH_UBSAN = yes])
+
+on_exit 'kill $(cat *.pid)'
+
+# Start the daemon and make sure that the pidfile exists immediately.
+# We don't wait for the pidfile to get created because the daemon is
+# supposed to do so before the parent exits.
+AT_CHECK([ovsdb-server --detach --monitor --no-chdir --pidfile --no-db --log-file=`pwd`/ovsdb-server.log --verbose=DBG], [0], [ignore], [ignore])
+AT_CHECK([test -s ovsdb-server.pid])
+child=$(cat ovsdb-server.pid)
+
+# Check process naming and ancestry.
+monitor=$(parent_pid $child)
+check_process_name $child ovsdb-server
+check_ancestors $child $monitor 1
+
+# Kill the daemon process, making it look like a segfault,
+# and wait for a new daemon process to get spawned.
+AT_CHECK([kill -SEGV $child], [0])
+OVS_WAIT_WHILE([kill -0 $child])
+OVS_WAIT_UNTIL([test -s ovsdb-server.pid && test `cat ovsdb-server.pid` != $child])
+child2=$(cat ovsdb-server.pid)
+
+# Check process naming and ancestry.
+check_process_name $child2 ovsdb-server
+check_ancestors $child2 $monitor 1
+
+# Kill the daemon process with SIGTERM, and wait for the daemon
+# and the monitor processes to go away and the pidfile to get deleted.
+AT_CHECK([kill $child2])
+OVS_WAIT_WHILE([kill -0 $monitor || kill -0 $child2 || test -e ovsdb-server.pid])
+
+AT_CHECK([grep -q "fatal_signal|DBG|Load needed libraries by capturing dummy backtrace" ovsdb-server.log])
+AT_CHECK([grep -q "^SIGSEGV detected, backtrace:" ovsdb-server.log])
+AT_CHECK([grep -q "daemon_unix(monitor)|ERR|1 crashes: pid .* died, killed (Segmentation fault), core dumped, restarting" ovsdb-server.log])
+
+AT_CLEANUP