varnishevent: improve signal handling, log stack trace on failure

bin/varnishevent/Makefile.am

@@ -9,6 +9,7 @@ dist_man_MANS = varnishevent.1
 varnishevent_SOURCES = \
 	varnishevent.c \
 	varnishevent.h \
+	signals.h \
 	base64.c \
 	base64.h \
 	data.c \
@@ -18,6 +19,7 @@ varnishevent_SOURCES = \
 	log.c \
 	monitor.c \
 	format.c \
+	handler.c \
 	$(top_builddir)/lib/libvarnish/assert.c \
 	$(top_builddir)/lib/libvarnish/flopen.c \
 	$(top_builddir)/lib/libvarnish/version.c \

bin/varnishevent/handler.c

+/*-
+ * Copyright (c) 2012 UPLEX Nils Goroll Systemoptimierung
+ * Copyright (c) 2012 Otto Gmbh & Co KG
+ * All rights reserved
+ * Use only with permission
+ *
+ * Authors: Geoffrey Simmons <geoffrey.simmons@uplex.de>
+ *	    Nils Goroll <nils.goroll@uplex.de>
+ *
+ * Portions adopted from varnishlog.c from the Varnish project
+ *	Author: Poul-Henning Kamp <phk@phk.freebsd.dk>
+ * 	Copyright (c) 2006 Verdens Gang AS
+ * 	Copyright (c) 2006-2011 Varnish Software AS
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ * 1. Redistributions of source code must retain the above copyright
+ *    notice, this list of conditions and the following disclaimer.
+ * 2. Redistributions in binary form must reproduce the above copyright
+ *    notice, this list of conditions and the following disclaimer in the
+ *    documentation and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
+ * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
+ * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
+ * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
+ * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
+ * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
+ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+ * SUCH DAMAGE.
+ *
+ */
+
+#include "config.h"
+
+#include <signal.h>
+#include <string.h>
+#include <syslog.h>
+#include <stdlib.h>
+#include <ctype.h>
+
+#ifndef HAVE_EXECINFO_H
+#include "compat/execinfo.h"
+#else
+#include <execinfo.h>
+#endif
+
+#include "vas.h"
+#include "vsb.h"
+
+#include "varnishevent.h"
+
+/* XXX: configurable? */
+#define MAX_STACK_DEPTH 100
+
+/*--------------------------------------------------------------------*/
+
+/*
+ * This hack is almost verbatim from varnishd.c -- attempt to run nm(1) on
+ * ourselves at startup to get a mapping from lib pointers to symbolic
+ * function names for stack traces.
+ *
+ * +1 to phk's rant in varnishd.c about the lack of a standard for this.
+ */
+
+struct symbols {
+    uintptr_t               a;
+    char                    *n;
+    VTAILQ_ENTRY(symbols)   list;
+};
+
+static VTAILQ_HEAD(,symbols) symbols = VTAILQ_HEAD_INITIALIZER(symbols);
+
+static int
+symbol_lookup(struct vsb *vsb, void *ptr)
+{
+    struct symbols *s, *s0;
+    uintptr_t pp;
+
+    pp = (uintptr_t)ptr;
+    s0 = NULL;
+    VTAILQ_FOREACH(s, &symbols, list) {
+        if (s->a > pp)
+            continue;
+        if (s0 == NULL || s->a > s0->a)
+            s0 = s;
+    }
+    if (s0 == NULL)
+        return (-1);
+    VSB_printf(vsb, "%p: %s+%jx", ptr, s0->n, (uintmax_t)pp - s0->a);
+    return (0);
+}
+
+static void
+symbol_hack(const char *a0)
+{
+    char buf[BUFSIZ], *p, *e;
+    FILE *fi;
+    uintptr_t a;
+    struct symbols *s;
+
+    sprintf(buf, "nm -an %s 2>/dev/null", a0);
+    fi = popen(buf, "r");
+    if (fi == NULL)
+        return;
+    while (fgets(buf, sizeof buf, fi)) {
+        if (buf[0] == ' ')
+            continue;
+        p = NULL;
+        a = strtoul(buf, &p, 16);
+        if (p == NULL)
+            continue;
+        if (a == 0)
+            continue;
+        if (*p++ != ' ')
+            continue;
+        p++;
+        if (*p++ != ' ')
+            continue;
+        if (*p <= ' ')
+            continue;
+        e = strchr(p, '\0');
+        AN(e);
+        while (e > p && isspace(e[-1]))
+            e--;
+        *e = '\0';
+        s = malloc(sizeof *s + strlen(p) + 1);
+        AN(s);
+        s->a = a;
+        s->n = (void*)(s + 1);
+        strcpy(s->n, p);
+        VTAILQ_INSERT_TAIL(&symbols, s, list);
+    }
+    (void)pclose(fi);
+}
+
+static void
+stacktrace(void)
+{
+    void *buf[MAX_STACK_DEPTH];
+    int depth, i;
+    struct vsb *sb = VSB_new_auto();
+
+    depth = backtrace (buf, MAX_STACK_DEPTH);
+    if (depth == 0) {
+        LOG_Log0(LOG_ERR, "Stacktrace empty");
+        return;
+    }
+    for (i = 0; i < depth; i++) {
+        VSB_clear(sb);
+        if (symbol_lookup(sb, buf[i]) < 0) {
+            char **strings;
+            strings = backtrace_symbols(&buf[i], 1);
+            if (strings != NULL && strings[0] != NULL)
+                VSB_printf(sb, "%p: %s", buf[i], strings[0]);
+            else
+                VSB_printf(sb, "%p: (?)", buf[i]);
+        }
+        VSB_finish(sb);
+        LOG_Log(LOG_ERR, "%s", VSB_data(sb));
+    }
+}
+
+void
+HNDL_Init(const char *a0)
+{
+    symbol_hack(a0);
+}
+
+void
+HNDL_Abort(int sig)
+{
+    AZ(sigaction(SIGABRT, &default_action, NULL));
+    LOG_Log(LOG_ALERT, "Received signal %d (%s), stacktrace follows", sig,
+        strsignal(sig));
+    stacktrace();
+    DATA_Dump();
+    MON_Output();
+    LOG_Log0(LOG_ALERT, "Aborting");
+    abort();
+}

bin/varnishevent/monitor.c

@@ -85,6 +85,12 @@ monitor_main(void *arg)
     pthread_exit((void *) NULL);
 }
 
+void
+MON_Output(void)
+{
+    log_output();
+}
+
 void
 MON_Shutdown(void)
 {

bin/varnishevent/signals.h

+/*-
+ * Copyright (c) 2012 UPLEX Nils Goroll Systemoptimierung
+ * Copyright (c) 2012 Otto Gmbh & Co KG
+ * All rights reserved
+ * Use only with permission
+ *
+ * Author: Geoffrey Simmons <geoffrey.simmons@uplex.de>
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met:
+ * 1. Redistributions of source code must retain the above copyright
+ *    notice, this list of conditions and the following disclaimer.
+ * 2. Redistributions in binary form must reproduce the above copyright
+ *    notice, this list of conditions and the following disclaimer in the
+ *    documentation and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
+ * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
+ * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
+ * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
+ * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
+ * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
+ * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+ * SUCH DAMAGE.
+ *
+ */
+
+
+SIGDISP(SIGTERM, terminate_action);
+SIGDISP(SIGINT, terminate_action);
+SIGDISP(SIGUSR1, dump_action);
+SIGDISP(SIGUSR2, ignore_action);
+SIGDISP(SIGABRT, stacktrace_action);
+SIGDISP(SIGSEGV, stacktrace_action);
+SIGDISP(SIGBUS, stacktrace_action);

bin/varnishevent/varnishevent.c

@@ -112,7 +112,22 @@ static struct insert_head_s insert_head = VTAILQ_HEAD_INITIALIZER(insert_head);
 static unsigned seen = 0, open = 0, submitted = 0, not_logged = 0, occ_hi = 0,
     waits = 0, len_overflows = 0, hdr_overflows = 0, expired = 0;
 
-static volatile sig_atomic_t reopen;
+/* Hack, because we cannot have #ifdef in the macro definition SIGDISP */
+#define _UNDEFINED(SIG) ((#SIG)[0] == 0)
+#define UNDEFINED(SIG) _UNDEFINED(SIG)
+
+#define SIGDISP(SIG, action)						\
+    do { if (UNDEFINED(SIG)) break;					\
+        if (sigaction((SIG), (&action), NULL) != 0)			\
+            LOG_Log(LOG_ALERT,						\
+                "Cannot install handler for " #SIG ": %s",		\
+                strerror(errno));					\
+    } while(0)
+
+static struct sigaction dump_action, terminate_action, reopen_action,
+    stacktrace_action, ignore_action;
+
+static volatile sig_atomic_t reopen = 0, term = 0;
 
 struct VSM_data *vd;
 
@@ -159,6 +174,8 @@ static inline logline_t
             LOG_Log0(LOG_DEBUG, "Reader: waiting for free space");
             waiting = 1;
             AZ(pthread_mutex_lock(&data_ready_lock));
+            if (WRT_Waiting())
+                AZ(pthread_cond_signal(&spscq_ready_cond));
             AZ(pthread_cond_wait(&data_ready_cond, &data_ready_lock));
             rdr_free = DATA_Take_Freelist(&reader_freelist);
             waiting = 0;
@@ -329,15 +346,18 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
 }
 
 static int
-h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd,
+event(void *priv, enum VSL_tag_e tag, unsigned fd,
     unsigned len, unsigned spec, const char *ptr, uint64_t bitmap)
 {
-    struct logline_t *lp;
+    struct logline_t *lp = NULL;
 
     static double last_housekeep = 0.0;
 
     (void) priv;
 
+    if (term && open == 0)
+        return 1;
+    
     LOG_Log(LOG_DEBUG, "Data: [%u %s %c %.*s]", fd, VSL_tags[tag],
         C(spec) ? 'c' : B(spec) ? 'b' : '-', len, ptr);
     
@@ -355,7 +375,7 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd,
         CHECK_OBJ_NOTNULL(lp, LOGLINE_MAGIC);
         assert(lp->state == DATA_OPEN);
     }
-    else {
+    else if (!term) {
         double t;
         
         AZ(fd_tbl[fd].ll);
@@ -391,17 +411,19 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd,
         }
     }
 
-    collect(lp, tag, spec, ptr, len);
-
-    lp->bitmap |= bitmap;
-    if (fd == 0)
-        lp->state = DATA_DONE;
+    if (lp) {
+        collect(lp, tag, spec, ptr, len);
+        
+        lp->bitmap |= bitmap;
+        if (fd == 0)
+            lp->state = DATA_DONE;
 
-    if (lp->state == DATA_DONE) {
-        submit(&fd_tbl[fd]);
-        fd_free(&fd_tbl[fd]);
+        if (lp->state == DATA_DONE) {
+            submit(&fd_tbl[fd]);
+            fd_free(&fd_tbl[fd]);
+        }
     }
-
+    
     return reopen;
 }
 
@@ -421,6 +443,26 @@ dump(int sig)
     DATA_Dump();
 }
 
+static void
+terminate(int sig)
+{
+    (void) sig;
+    term = 1;
+}
+
+static void
+assert_fail(const char *func, const char *file, int line, const char *cond,
+    int err, int xxx)
+{
+    (void) xxx;
+    
+    LOG_Log(LOG_ALERT, "Condition (%s) failed in %s(), %s line %d",
+        cond, func, file, line);
+    if (err)
+        LOG_Log(LOG_ALERT, "errno = %d (%s)", err, strerror(err));
+    abort();
+}
+
 /*--------------------------------------------------------------------*/
 
 static void
@@ -441,16 +483,16 @@ usage(void)
 {
 
     fprintf(stderr,
-        "usage: varnishncsa %s [-aDV] [-n varnish_name] "
-        "[-P file] [-w file]\n", VSL_USAGE);
+        "usage: varnishevent %s [-aDVg] [-n varnish_name] "
+        "[-G configfile] [-P pidfile] [-w outputfile]\n", VSL_USAGE);
     exit(1);
 }
 
 int
 main(int argc, char *argv[])
 {
-    int c, errnum;
-    int a_flag = 0, g_flag = 0, D_flag = 0, format_flag = 0;
+    int c, errnum, finite = 0, a_flag = 0, g_flag = 0, D_flag = 0,
+        format_flag = 0;
     const char *P_arg = NULL, *w_arg = NULL;
     char scratch[BUFSIZ], cformat[BUFSIZ];
     struct vpf_fh *pfh = NULL;
@@ -498,6 +540,11 @@ main(int argc, char *argv[])
         case 'G':
             strcpy(cli_config_filename, optarg);
             break;
+        case 'r':
+            if (VSL_Arg(vd, c, optarg) > 0)
+                usage();
+            finite = 1;
+            break;
         case 'b':
         case 'i':
         case 'I':
@@ -544,13 +591,37 @@ main(int argc, char *argv[])
         exit(1);
     }
 
+    terminate_action.sa_handler = terminate;
+    AZ(sigemptyset(&terminate_action.sa_mask));
+    terminate_action.sa_flags &= ~SA_RESTART;
+
+    dump_action.sa_handler = dump;
+    AZ(sigemptyset(&dump_action.sa_mask));
+    dump_action.sa_flags |= SA_RESTART;
+
+    reopen_action.sa_handler = sighup;
+    AZ(sigemptyset(&reopen_action.sa_mask));
+    reopen_action.sa_flags |= SA_RESTART;
+
+    stacktrace_action.sa_handler = HNDL_Abort;
+
+    ignore_action.sa_handler = SIG_IGN;
+    default_action.sa_handler = SIG_DFL;
+
+    HNDL_Init(argv[0]);
+
+    /* Install signal handlers */
+#include "signals.h"
+
     if (pfh != NULL)
         VPF_Write(pfh);
     
     if (w_arg)
         strcpy(config.output_file, w_arg);
     if (!EMPTY(config.output_file))
-        signal(SIGHUP, sighup);
+        SIGDISP(SIGHUP, reopen_action);
+    else
+        SIGDISP(SIGHUP, ignore_action);
     if (a_flag)
         config.append = 1;
 
@@ -562,11 +633,27 @@ main(int argc, char *argv[])
 
     LOG_Log(LOG_INFO, "initializing (%s)", VCS_version);
 
+    VAS_Fail = assert_fail;
+
     if (FMT_Init(scratch) != 0) {
         LOG_Log(LOG_ALERT, "Error in output formats: %s", scratch);
         exit(EXIT_FAILURE);
     }
 
+    strcpy(scratch, VSM_Name(vd));
+    if (EMPTY(scratch))
+        LOG_Log0(LOG_INFO, "Reading default varnish instance");
+    else
+        LOG_Log(LOG_INFO, "Reading varnish instance %s", scratch);
+
+    strcpy(scratch, FMT_Get_i_Arg());
+    if (EMPTY(scratch)) {
+        LOG_Log0(LOG_ALERT, "Not configured to read any log data, exiting");
+        exit(EXIT_FAILURE);
+    }
+    assert(VSL_Arg(vd, 'i', scratch) > 0);
+    LOG_Log(LOG_INFO, "Reading SHM tags: %s", scratch);
+    
     if (!EMPTY(config.cformat))
         cb_flag |= VSL_S_CLIENT;
     if (!EMPTY(config.bformat))
@@ -586,8 +673,6 @@ main(int argc, char *argv[])
         exit(EXIT_FAILURE);
     }
 
-    signal(SIGUSR1, dump);
-    
     fd_tbl = (fd_t *) calloc(config.max_fd, sizeof(fd_t));
     if (fd_tbl == NULL) {
         LOG_Log(LOG_ALERT, "Cannot init fd table: %s\n", strerror(errno));
@@ -624,24 +709,27 @@ main(int argc, char *argv[])
         TIM_sleep(1);
     }
 
-    strcpy(scratch, VSM_Name(vd));
-    if (EMPTY(scratch))
-        LOG_Log0(LOG_INFO, "Reading default varnish instance");
-    else
-        LOG_Log(LOG_INFO, "Reading varnish instance %s", scratch);
-
-    strcpy(scratch, FMT_Get_i_Arg());
-    assert(VSL_Arg(vd, 'i', scratch) > 0);
-    LOG_Log(LOG_INFO, "Reading SHM tags: %s", scratch);
-    
-    while (VSL_Dispatch(vd, h_ncsa, NULL) >= 0)
-        if (reopen)
+    /* Main loop */
+    term = 0;
+    /* XXX: TERM not noticed until request received */
+    while (VSL_Dispatch(vd, event, NULL) >= 0)
+        if (term || finite)
+            break;
+        else if (reopen)
             WRT_Reopen();
+        else
+            LOG_Log0(LOG_WARNING, "Log read interrupted, continuing");
 
+    if (term)
+        LOG_Log0(LOG_INFO, "Termination signal received");
+    else if (!finite)
+        LOG_Log0(LOG_WARNING, "Varnish log closed");
+    
     WRT_Halt();
     MON_Shutdown();
     FMT_Shutdown();
+    LOG_Log0(LOG_INFO, "Exiting");
     LOG_Close();
 
-    exit(0);
+    exit(EXIT_SUCCESS);
 }

bin/varnishevent/varnishevent.h

@@ -34,6 +34,7 @@
 #include <pthread.h>
 #include <sys/types.h>
 #include <limits.h>
+#include <signal.h>
 
 #include "varnishapi.h"
 #include "vqueue.h"
@@ -60,6 +61,8 @@
 #define ALT_CFORMAT \
   "%{X-Forwarded-For}i %l %u %t \"%r\" %s %b \"%{Referer}i\" \"%{User-agent}i\""
 
+struct sigaction default_action;
+    
 typedef enum {
     DATA_EMPTY = 0,
     DATA_OPEN,
@@ -237,6 +240,7 @@ typedef enum {
 void MON_Start(void);
 void MON_Shutdown(void);
 void MON_StatsUpdate(stats_update_t update);
+void MON_Output(void);
 
 /* format.c */
 int FMT_Init(char *err);
@@ -245,3 +249,7 @@ int FMT_Get_nTags(void);
 int FMT_Read_Hdr(enum VSL_tag_e tag);
 void FMT_Format(logline_t *ll, struct vsb *os);
 void FMT_Shutdown(void);
+
+/* handler.c */
+void HNDL_Init(const char *a0);
+void HNDL_Abort(int sig);