Add debug facilities to log stack trace in case of segment fault.

Makefile

@@ -7,7 +7,7 @@ all::
 
 ### Defaults
 
-BASIC_CFLAGS = -O2 -std=c99 -pedantic -Wall -I./argparse
+BASIC_CFLAGS = -O2 -std=c99 -Wall -I./argparse
 BASIC_LDFLAGS = -lm -lsodium
 
 # Guard against environment variables
@@ -86,6 +86,7 @@ LIB_OBJS += rfc1035.o
 LIB_OBJS += safe_rw.o
 LIB_OBJS += cert.o
 LIB_OBJS += pidfile.o
+LIB_OBJS += debug.o
 
 DEP_LIBS += argparse/libargparse.a
 

compat.h

@@ -43,4 +43,19 @@
 #define ARRAY_SIZE(x) (sizeof(x)/sizeof(x[1]))
 #define COMPILER_ASSERT(X) (void) sizeof(char[(X) ? 1 : -1])
 
+/* Test for backtrace() */
+#if defined(__APPLE__) || defined(__linux__)
+#define HAVE_BACKTRACE 1
+#endif
+
+#if defined(__linux__) || defined(__OpenBSD__)
+#define _XOPEN_SOURCE 700
+/*
+ *  * On NetBSD, _XOPEN_SOURCE undefines _NETBSD_SOURCE and
+ *   * thus hides inet_aton etc.
+ *    */
+#elif !defined(__NetBSD__)
+#define _XOPEN_SOURCE
+#endif
+
 #endif

debug.c

@@ -0,0 +1,110 @@
+#include "debug.h"
+#include "logger.h"
+
+static char *assert_err  = "<no assertion failed>";
+static char *assert_file = "<no file>";
+static int assert_line   = 0;
+
+void
+_debug_assert(char *err, char *file, int line)
+{
+    logger(LOG_WARNING, "=== ASSERTION FAILED ===");
+    logger(LOG_WARNING, "%s:%d '%s' is not true", file, line, err);
+    assert_err  = err;
+    assert_file = file;
+    assert_line = line;
+    // force SIGSEGV to print the bug report
+    *((char *)-1) = 'x';
+}
+
+void
+debug_init(void)
+{
+    struct sigaction act;
+    sigemptyset(&act.sa_mask);
+    act.sa_flags     = SA_NODEFER | SA_RESETHAND | SA_SIGINFO;
+    act.sa_sigaction = debug_segv_handler;
+    sigaction(SIGSEGV, &act, NULL);
+    sigaction(SIGBUS, &act, NULL);
+    sigaction(SIGFPE, &act, NULL);
+    sigaction(SIGILL, &act, NULL);
+}
+
+#ifdef HAVE_BACKTRACE
+#include <execinfo.h>
+#include <ucontext.h>
+static void *
+getMcontextEip(ucontext_t *uc)
+{
+#if defined(__APPLE__) && !defined(MAC_OS_X_VERSION_10_6)
+    /* OSX < 10.6 */
+    #if defined(__x86_64__)
+    return (void *) uc->uc_mcontext->__ss.__rip;
+    #elif defined(__i386__)
+    return (void *) uc->uc_mcontext->__ss.__eip;
+    #else
+    return (void *) uc->uc_mcontext->__ss.__srr0;
+    #endif
+#elif defined(__APPLE__) && defined(MAC_OS_X_VERSION_10_6)
+    /* OSX >= 10.6 */
+    #if defined(_STRUCT_X86_THREAD_STATE64) && !defined(__i386__)
+    return (void *) uc->uc_mcontext->__ss.__rip;
+    #else
+    return (void *) uc->uc_mcontext->__ss.__eip;
+    #endif
+#elif defined(__linux__)
+    /* Linux */
+    #if defined(__i386__)
+    return (void *) uc->uc_mcontext.gregs[14]; /* Linux 32 */
+    #elif defined(__X86_64__) || defined(__x86_64__)
+    return (void *) uc->uc_mcontext.gregs[16]; /* Linux 64 */
+    #elif defined(__ia64__)                    /* Linux IA64 */
+    return (void *) uc->uc_mcontext.sc_ip;
+    #endif
+#else
+    return NULL;
+#endif
+}
+
+/**
+ * Logs the stack trace using the backtrace() call. This function is designed to
+ * be called from signal handlers safely.
+ */
+static void
+log_stack_trace(ucontext_t *uc)
+{
+    void *trace[100];
+    int trace_size = 0;
+    int fd         = logger_fd >= 0 ? logger_fd : STDOUT_FILENO;
+    /* Generate the stack trace */
+    trace_size = backtrace(trace, 100);
+    /* overwrite sigaction with caller's address */
+    if (getMcontextEip(uc) != NULL)
+        trace[1] = getMcontextEip(uc);
+
+    backtrace_symbols_fd(trace, trace_size, fd);
+}
+
+#endif
+
+void
+debug_segv_handler(int sig, siginfo_t *info, void *secret)
+{
+    logger(LOG_WARNING, "Crashed by signal: %d", sig);
+    logger(LOG_WARNING, "--- STACK TRACE");
+    logger(LOG_WARNING, "Failed assertion: %s (%s:%d)", assert_err, assert_file,
+           assert_line);
+#ifdef HAVE_BACKTRACE
+    logger(LOG_WARNING, "--- STACK TRACE");
+    ucontext_t *uc = (ucontext_t *) secret;
+    log_stack_trace(uc);
+#endif
+    /* Make sure we exit with the right signal at the end. So for instance
+     * the core will be dumped if enabled. */
+    struct sigaction act;
+    sigemptyset(&act.sa_mask);
+    act.sa_flags   = SA_NODEFER | SA_ONSTACK | SA_RESETHAND;
+    act.sa_handler = SIG_DFL;
+    sigaction(sig, &act, NULL);
+    kill(getpid(), sig);
+}

debug.h

@@ -0,0 +1,15 @@
+#ifndef DEBUG_H
+#define DEBUG_H
+/**
+ * Debug facilities.
+ */
+
+#include "compat.h"
+
+#define debug_assert(e) ((e) ? (void)0 : (_debug_assert(#e, __FILE__, __LINE__), _exit(1)))
+void _debug_assert(char *err, char *file, int line);
+
+void debug_init(void);
+void debug_segv_handler(int sig, siginfo_t *info, void *secret);
+
+#endif

dnscrypt.h

@@ -3,6 +3,7 @@
 
 #include "compat.h"
 #include "tree.h"
+#include "debug.h"
 #include <event2/event.h>
 #include <event2/listener.h>
 #include <event2/bufferevent.h>

logger.c

@@ -1,34 +1,33 @@
 #include "logger.h"
-#include "compat.h"
 
-int logger_verbosity = LOG_DEBUG;
+int logger_verbosity = LOG_INFO;
 char *logger_logfile = NULL;
+int logger_fd = -1;
 
-// prioritynames (from <syslog.h>)
-#define	INTERNAL_NOPRI	0x10    /* the "no priority" priority */
+#define LOGGER_LINESIZE 1024
+
+// priority names (from <syslog.h>)
+#define INTERNAL_NOPRI 0x10     /* the "no priority" priority */
 typedef struct _code {
     const char *c_name;
     int c_val;
 } CODE;
 
 CODE prioritynames[] = {
-    {"alert", LOG_ALERT,},
-    {"crit", LOG_CRIT,},
-    {"debug", LOG_DEBUG,},
-    {"emerg", LOG_EMERG,},
-    {"err", LOG_ERR,},
-    {"error", LOG_ERR,},        /* DEPRECATED */
-    {"info", LOG_INFO,},
-    {"none", INTERNAL_NOPRI,},  /* INTERNAL */
-    {"notice", LOG_NOTICE,},
-    {"panic", LOG_EMERG,},      /* DEPRECATED */
-    {"warn", LOG_WARNING,},     /* DEPRECATED */
-    {"warning", LOG_WARNING,},
-    {NULL, -1,}
+    {"emerg", LOG_EMERG},
+    {"alert", LOG_ALERT},
+    {"crit", LOG_CRIT},
+    {"err", LOG_ERR},
+    {"warning", LOG_WARNING},
+    {"notice", LOG_NOTICE},
+    {"info", LOG_INFO},
+    {"debug", LOG_DEBUG},
+    {"none", INTERNAL_NOPRI},   /* INTERNAL */
+    {NULL, -1}
 };
 
 void
-logger(int priority, const char *fmt, ...)
+_logger(int priority, const char *fmt, ...)
 {
     va_list ap;
     char msg[LOGGER_MAXLEN];
@@ -43,7 +42,26 @@ logger(int priority, const char *fmt, ...)
     logger_lograw(priority, msg);
 }
 
-/* 
+void
+_logger_with_fileline(int priority, const char *fmt, const char *file, int line,
+                      ...)
+{
+    va_list ap;
+    char msg[LOGGER_MAXLEN];
+
+    if (priority > logger_verbosity)
+        return;
+
+    size_t n = snprintf(msg, sizeof(msg), "[%s:%d] ", file, line);
+
+    va_start(ap, line);
+    vsnprintf(msg + n, sizeof(msg), fmt, ap);
+    va_end(ap);
+
+    logger_lograw(priority, msg);
+}
+
+/*
  * Low-level logging. It's only used when you want to log arbitrary length message.
  */
 void
@@ -59,6 +77,12 @@ logger_lograw(int priority, const char *msg)
     if (priority < 0 || priority > LOG_PRIMASK)
         priority = INTERNAL_NOPRI;
 
+    if (logger_fd < 0) {
+        logger_reopen();
+    }
+    if (logger_fd < 0) {
+        return;
+    }
     fp = (logger_logfile == NULL) ? stdout : fopen(logger_logfile, "a");
     if (!fp)
         return;
@@ -69,16 +93,38 @@ logger_lograw(int priority, const char *msg)
             priority_flag = c.c_name;
         }
     }
+    assert(priority_flag);
 
+    // prefix
     int off;
     struct timeval tv;
     gettimeofday(&tv, NULL);
     char buf[64];
     off = strftime(buf, sizeof(buf), "%d %b %H:%M:%S.", localtime(&tv.tv_sec));
     snprintf(buf + off, sizeof(buf) - off, "%03d", (int)tv.tv_usec / 1000);
-    fprintf(fp, "[%d] %s [%s] %s\n", (int)getpid(), buf, priority_flag, msg);
-    fflush(fp);
+    // format log
+    char logbuf[LOGGER_LINESIZE];
+    size_t len = snprintf(logbuf, LOGGER_LINESIZE, "[%d] %s [%s] %s\n",
+                          (int)getpid(), buf, priority_flag, msg);
+    // write
+    write(logger_fd, logbuf, len);
+}
 
-    if (logger_logfile)
-        fclose(fp);
+void
+logger_reopen(void)
+{
+    if (logger_logfile) {
+        logger_fd = open(logger_logfile, O_APPEND | O_CREAT | O_WRONLY, 0644);
+    } else {
+        logger_fd = STDOUT_FILENO;
+    }
+}
+
+void
+logger_close(void)
+{
+    if (logger_fd >= 0) {
+        close(logger_fd);
+    }
+    logger_fd = -1;
 }

logger.h

@@ -1,5 +1,12 @@
 #ifndef LOGGER_H
 #define LOGGER_H
+/**
+ * Logger
+ *
+ * @link http://en.wikipedia.org/wiki/Syslog
+ */
+
+#include "compat.h"
 
 #ifndef _WIN32
 #include <syslog.h>
@@ -21,7 +28,15 @@
 extern int logger_verbosity;
 extern char *logger_logfile;
 
-void logger(int priority, const char *fmt, ...);
+/* Global Variables. */
+extern int logger_fd;
+
+// see http://stackoverflow.com/q/5588855/288089
+#define logger(p, fmt, ...) _logger_with_fileline((p), (fmt), __FILE__, __LINE__, ##__VA_ARGS__)
+void _logger(int priority, const char *fmt, ...);
+void _logger_with_fileline(int priority, const char *fmt, const char *file, int line, ...);
 void logger_lograw(int priority, const char *msg);
+void logger_reopen(void);
+void logger_close(void);
 
 #endif

main.c

@@ -235,6 +235,8 @@ main(int argc, const char **argv)
         return 1;
     }
 
+    debug_init();
+
     if (gen_provider_keypair) {
         uint8_t provider_publickey[crypto_sign_ed25519_PUBLICKEYBYTES];
         uint8_t provider_secretkey[crypto_sign_ed25519_SECRETKEYBYTES];

version.h

@@ -2,6 +2,6 @@
 #ifndef VERSION_H
 #define VERSION_H
 
-const char *the_version = "0.1.15.11.g3278df5";
+const char *the_version = "0.1.15.17.gfc8126d";
 
 #endif