varnishevent - reader doesn't save data for b/c unless requested

	- added debugging
	- read closing tags for client and/or backend requests

bin/varnishevent/data.c

@@ -31,19 +31,22 @@
 
 #include <pthread.h>
 #include <stdlib.h>
+#include <syslog.h>
 
 #include "varnishevent.h"
 #include "vas.h"
 #include "miniobj.h"
 #include "vqueue.h"
+#include "vsb.h"
 
-#if 0
 static const char *statename[3] = { "EMPTY", "OPEN", "DONE" };
-#endif
 
 static pthread_mutex_t freelist_lock;
 static char *bufptr;
 
+#define C(spec) ((spec) & VSL_S_CLIENT)
+#define B(spec) ((spec) & VSL_S_BACKEND)
+
 #if 0
 static void
 data_Cleanup(void)
@@ -145,14 +148,56 @@ DATA_Return_Freelist(struct freehead_s *returned, unsigned nreturned)
     AZ(pthread_mutex_unlock(&freelist_lock));
 }
 
-#if 0
+#define DUMP_HDRS(vsb, ll, hdr) do {                                    \
+for (j = 0; j < ll->hdr.nrec; j++)                                      \
+    if (ll->hdr.record[j].len) {                                        \
+        VSB_putc(vsb, '[');                                             \
+        VSB_bcat(vsb, ll->hdr.record[j].data, ll->hdr.record[j].len);   \
+        VSB_cat(vsb, "] ");                                             \
+    }                                                                   \
+ } while (0)
+
 void
 DATA_Dump(void)
 {
-    for (int i = 0; i < MAXDATA; i++)
-        if (logline[i].state != DATA_EMPTY)
-            LOG_Log(LOG_INFO, "Data entry %d: XID=%d tid=%d state=%s data=[%.*s]",
-                i, entry->xid, entry->tid, statename[entry->state], entry->end,
-                entry->data);
+    struct vsb *data;
+    logline_t *ll;
+
+    data = VSB_new_auto();
+    
+    for (int i = 0; i < config.max_data; i++) {
+        int j;
+        
+        if (logline[i].state == DATA_EMPTY)
+            continue;
+
+        ll = &logline[i];
+        VSB_clear(data);
+        
+        VSB_printf(data, "Data entry %d: state=%s dir=%c tags={",
+            i, statename[ll->state],
+            C(ll->spec) ? 'c' : B(ll->spec) ? 'b' : '-');
+        
+        for (j = 0; j < MAX_VSL_TAG; j++)
+            if (ll->tag[j].len) {
+                VSB_cat(data, VSL_tags[j]);
+                VSB_cat(data, "=[");
+                VSB_bcat(data, ll->tag[j].data, ll->tag[j].len);
+                VSB_cat(data, "] ");
+            }
+
+        VSB_cat(data, "} rx_headers={");
+        DUMP_HDRS(data, ll, rx_headers);
+
+        VSB_cat(data, "} tx_headers={");
+        DUMP_HDRS(data, ll, tx_headers);
+
+        VSB_cat(data, "} vcl_log={");
+        DUMP_HDRS(data, ll, vcl_log);
+        VSB_putc(data, '}');
+
+        VSB_finish(data);
+
+        LOG_Log(LOG_INFO, "%s", VSB_data(data));
+    }
 }
-#endif

bin/varnishevent/format.c

@@ -461,6 +461,14 @@ compile_fmt(char *format, compiled_fmt_t *fmt, unsigned spec, char *err)
     }
     memset(fmt->tags, 0, MAX_VSL_TAG);
 
+    /* always read the closing tags for clients and backends */
+    if (C(spec))
+        ADD_TAG(fmt->tags, ReqEnd);
+    else if (B(spec)) {
+        ADD_TAG(fmt->tags, BackendReuse);
+        ADD_TAG(fmt->tags, BackendClose);
+    }
+    
     n = 0;
     os = VSB_new_auto();
     

bin/varnishevent/varnishevent.c

@@ -100,14 +100,16 @@ typedef struct fd_t {
 
 static fd_t *fd_tbl;
 
-static unsigned seen = 0, open = 0, submitted = 0, occ_hi = 0, waits = 0,
-    len_overflows = 0, hdr_overflows = 0;
+static unsigned seen = 0, open = 0, submitted = 0, not_logged = 0, occ_hi = 0,
+    waits = 0, len_overflows = 0, hdr_overflows = 0;
 
 static volatile sig_atomic_t reopen;
 
 struct VSM_data *vd;
 
 static int m_flag = 0;
+static int cb_flag = 0;
+static int z_flag = 0;
 
 /* Local freelist */
 static struct freehead_s reader_freelist = 
@@ -128,11 +130,11 @@ void
 RDR_Stats(void)
 {
     LOG_Log(LOG_INFO, "Reader (%s): fd_max=%u seen=%u open=%u load=%.2f "
-        "submitted=%u occ_hi=%u waits=%u free=%u len_overflows=%u "
-        "hdr_overflows=%u",
+        "submitted=%u not_logged=%u occ_hi=%u waits=%u free=%u "
+        "len_overflows=%u hdr_overflows=%u",
         waiting ? "waiting" : "running", config.max_fd, seen, open,
-        100.0 * open / config.max_fd, submitted, occ_hi, waits, rdr_free,
-        len_overflows, hdr_overflows);
+        100.0 * open / config.max_fd, submitted, not_logged, occ_hi, waits,
+        rdr_free, len_overflows, hdr_overflows);
 }
 
 static inline logline_t
@@ -180,45 +182,6 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     hdr_t *hdr = NULL;
     record_t *rec = NULL;
 
-    if (spec & VSL_S_BACKEND || spec & VSL_S_CLIENT) {
-        if (!lp->spec)
-            lp->spec = spec;
-        else
-            assert(lp->spec == spec);
-    }
-
-    if (len > config.max_reclen) {
-        LOG_Log(LOG_ALERT,
-            "Data length %u exceeds max %u, DATA TRUNCATED: %s [%.*s]",
-            len, config.max_reclen, VSL_tags[tag], len, ptr);
-        len_overflows++;
-        len = config.max_reclen;
-    }
-
-    if (tag == SLT_RxHeader)
-        hdr = &lp->rx_headers;
-    else if (tag == SLT_TxHeader)
-        hdr = &lp->tx_headers;
-    else if (tag == SLT_VCL_Log)
-        hdr = &lp->vcl_log;
-
-    if (hdr != NULL) {
-        if (hdr->nrec < config.max_headers)
-            rec = &hdr->record[hdr->nrec++];
-        else {
-            LOG_Log(LOG_ALERT,
-                "Number of headers exceeds max %u, DATA DISCARDED: %s [%.*s]",
-                config.max_headers, VSL_tags[tag], len, ptr);
-            hdr_overflows++;
-            return;
-        }
-    }
-    else
-        rec = &lp->tag[tag];
-    
-    memcpy(rec->data, ptr, len);
-    rec->len = len;
-    
     switch (tag) {
     case SLT_BackendReuse:
     case SLT_BackendClose:
@@ -257,6 +220,48 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     default:
         break;
     }
+
+    if (spec & VSL_S_BACKEND || spec & VSL_S_CLIENT) {
+        if (!lp->spec)
+            lp->spec = spec;
+        else
+            assert(lp->spec == spec);
+    }
+
+    if (lp->spec && !(lp->spec & cb_flag))
+        return;
+        
+    if (len > config.max_reclen) {
+        LOG_Log(LOG_ALERT,
+            "Data length %u exceeds max %u, DATA TRUNCATED: %s [%.*s]",
+            len, config.max_reclen, VSL_tags[tag], len, ptr);
+        len_overflows++;
+        len = config.max_reclen;
+    }
+
+    if (tag == SLT_RxHeader)
+        hdr = &lp->rx_headers;
+    else if (tag == SLT_TxHeader)
+        hdr = &lp->tx_headers;
+    else if (tag == SLT_VCL_Log)
+        hdr = &lp->vcl_log;
+
+    if (hdr != NULL) {
+        if (hdr->nrec < config.max_headers)
+            rec = &hdr->record[hdr->nrec++];
+        else {
+            LOG_Log(LOG_ALERT,
+                "Number of headers exceeds max %u, DATA DISCARDED: %s [%.*s]",
+                config.max_headers, VSL_tags[tag], len, ptr);
+            hdr_overflows++;
+            return;
+        }
+    }
+    else
+        rec = &lp->tag[tag];
+    
+    memcpy(rec->data, ptr, len);
+    rec->len = len;
 }
 
 static int
@@ -267,6 +272,9 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd,
 
     (void) priv;
 
+    LOG_Log(LOG_DEBUG, "Data: [%u %s %c %.*s]", fd, VSL_tags[tag],
+        C(spec) ? 'c' : B(spec) ? 'b' : '-', len, ptr);
+    
     if (fd > config.max_fd) {
         LOG_Log(LOG_ALERT, "fd %u exceeds max %u: %s [%.*s]", fd, config.max_fd,
             VSL_tags[tag], len, ptr);
@@ -274,7 +282,7 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd,
     }
     
     /* XXX: handle these, esp. for Backend_health */
-    if (fd == 0)
+    if (fd == 0 && !z_flag)
         return 1;
     
     if (fd_tbl[fd].state == FD_EMPTY) {
@@ -308,12 +316,22 @@ 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->state == DATA_DONE) {
         logline->open--;
-        MON_StatsUpdate(STATS_DONE);
-        if (!m_flag || VSL_Matched(vd, lp->bitmap))
+        if ((m_flag && !VSL_Matched(vd, lp->bitmap))
+            || (lp->spec && !(lp->spec & cb_flag))) {
+            not_logged++;
+            DATA_Clear_Logline(lp);
+            rdr_free++;
+            VSTAILQ_INSERT_TAIL(&reader_freelist, lp, freelist);
+        }
+        else {
+            MON_StatsUpdate(STATS_DONE);
             submit(fd);
+        }
         fd_tbl[fd].state = FD_EMPTY;
         fd_tbl[fd].ll = NULL;
         open--;
@@ -331,6 +349,13 @@ sighup(int sig)
     reopen = 1;
 }
 
+static void
+dump(int sig)
+{
+    (void) sig;
+    DATA_Dump();
+}
+
 static FILE *
 open_log(const char *ofn, int append)
 {
@@ -368,10 +393,10 @@ int
 main(int argc, char *argv[])
 {
     int c, errnum;
-    int a_flag = 0, D_flag = 0, format_flag = 0;
+    int a_flag = 0, d_flag = 0, D_flag = 0, format_flag = 0;
     const char *P_arg = NULL;
     const char *w_arg = NULL;
-    char errstr[BUFSIZ], i_arg[BUFSIZ];
+    char scratch[BUFSIZ];
     struct vpf_fh *pfh = NULL;
     FILE *of;
 
@@ -379,11 +404,14 @@ main(int argc, char *argv[])
     VSL_Setup(vd);
     CONF_Init();
 
-    while ((c = getopt(argc, argv, VSL_ARGS "aDP:Vw:fF:")) != -1) {
+    while ((c = getopt(argc, argv, VSL_ARGS "adDP:Vw:fF:")) != -1) {
         switch (c) {
         case 'a':
             a_flag = 1;
             break;
+        case 'd':
+            d_flag = 1;
+            break;
         case 'f':
             if (format_flag) {
                 fprintf(stderr, "-f and -F can not be combined\n");
@@ -465,14 +493,23 @@ main(int argc, char *argv[])
     if (LOG_Open("varnishevent") != 0) {
         exit(EXIT_FAILURE);
     }
+    if (d_flag)
+        LOG_SetLevel(LOG_DEBUG);
 
     LOG_Log(LOG_INFO, "initializing (%s)", VCS_version);
 
-    if (FMT_Init(errstr) != 0) {
-        LOG_Log(LOG_ALERT, "Error in output formats: %s", errstr);
+    if (FMT_Init(scratch) != 0) {
+        LOG_Log(LOG_ALERT, "Error in output formats: %s", scratch);
         exit(EXIT_FAILURE);
     }
 
+    if (!EMPTY(config.cformat))
+        cb_flag |= VSL_S_CLIENT;
+    if (!EMPTY(config.bformat))
+        cb_flag |= VSL_S_BACKEND;
+    if (!EMPTY(config.zformat))
+        z_flag = 1;
+
     AZ(pthread_mutexattr_init(&attr_lock));
     AZ(pthread_condattr_init(&attr_cond));
 
@@ -485,6 +522,8 @@ 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));
@@ -516,11 +555,14 @@ main(int argc, char *argv[])
         TIM_sleep(1);
     }
 
-    FMT_Get_i_Arg(i_arg);
-    assert(VSL_Arg(vd, 'i', i_arg) > 0);
-    
-    LOG_Log(LOG_INFO, "Reading varnish instance %s, SHM tags: %s",
-        VSM_Name(vd), i_arg);
+    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);
+    FMT_Get_i_Arg(scratch);
+    assert(VSL_Arg(vd, 'i', scratch) > 0);
+    LOG_Log(LOG_INFO, "Reading SHM tags: %s", scratch);
     
     while (VSL_Dispatch(vd, h_ncsa, of) >= 0) {
         if (fflush(of) != 0) {

bin/varnishevent/varnishevent.h

@@ -38,6 +38,9 @@
 #include "vqueue.h"
 #include "vsb.h"
 
+#define C(spec) ((spec) & VSL_S_CLIENT)
+#define B(spec) ((spec) & VSL_S_BACKEND)
+
 /* Defaults from Varnish 3.0.3 */
 #define DEFAULT_MAX_RECLEN 255	/* shm_reclen */
 #define DEFAULT_MAX_HEADERS 64	/* http_max_hdr */
@@ -196,6 +199,7 @@ int DATA_Init(void);
 void DATA_Clear_Logline(logline_t *ll);
 unsigned DATA_Take_Freelist(struct freehead_s *dst);
 void DATA_Return_Freelist(struct freehead_s *returned, unsigned nreturned);
+void DATA_Dump(void);
 
 /* writer.c */
 int WRT_Init(FILE *out);