varnishevent: handle client/backend spec mismatches more robustly

bin/varnishevent/format.c

@@ -544,6 +544,15 @@ compile_fmt(char *format, compiled_fmt_t *fmt, unsigned spec, char *err)
     }
     memset(fmt->tags, 0, MAX_VSL_TAG);
 
+    /* starting tags */
+    if (C(spec)) {
+        ADD_TAG(fmt->tags, SessionOpen);
+        ADD_TAG(fmt->tags, ReqStart);
+    }
+    if (B(spec)) {
+        ADD_TAG(fmt->tags, BackendOpen);
+        ADD_TAG(fmt->tags, BackendXID);
+    }
     /* always read the closing tags for clients and backends */
     if (C(spec) || B(spec)) {
         ADD_TAG(fmt->tags, ReqEnd);

bin/varnishevent/varnishevent.c

@@ -111,7 +111,7 @@ 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,
     len_hi = 0, waits = 0, fd_overflows = 0, len_overflows = 0,
-    hdr_overflows = 0, expired = 0;
+    hdr_overflows = 0, expired = 0, spec_mismatches = 0, wrong_tags = 0;
 
 /* Hack, because we cannot have #ifdef in the macro definition SIGDISP */
 #define _UNDEFINED(SIG) ((#SIG)[0] == 0)
@@ -162,10 +162,12 @@ RDR_Stats(void)
 {
     LOG_Log(LOG_INFO, "Reader (%s): fd_max=%u seen=%u open=%u load=%.2f "
         "submitted=%u not_logged=%u occ_hi=%u waits=%u expired=%u free=%u "
-        "len_hi=%u fd_overflows=%u len_overflows=%u hdr_overflows=%u",
+        "len_hi=%u fd_overflows=%u len_overflows=%u hdr_overflows=%u "
+        "spec_mismatches=%u wrong_tags=%u",
         waiting ? "waiting" : "running", config.max_fd, seen, open,
         100.0 * open / config.max_fd, submitted, not_logged, occ_hi, waits,
-        expired, rdr_free, len_hi, fd_overflows, len_overflows, hdr_overflows);
+        expired, rdr_free, len_hi, fd_overflows, len_overflows, hdr_overflows,
+        spec_mismatches, wrong_tags);
 }
 
 static inline logline_t
@@ -259,6 +261,18 @@ expire(double t)
     }
 }
 
+#define CB(spec) (C(spec) ? 'c' : B(spec) ? 'b' : '-')
+
+static inline void
+spec_mismatch(enum VSL_tag_e tag, unsigned saw, unsigned saved,
+    const char *ptr, unsigned len)
+{
+    LOG_Log(LOG_ALERT, "client/backend spec mismatch, saw '%c', "
+                       "was '%c', DATA DISCARDED: %s [%.*s]",
+        CB(saw), CB(saved), VSL_tags[tag], len, ptr);
+    spec_mismatches++;
+}
+
 static inline void
 collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     const char *ptr, unsigned len)
@@ -267,11 +281,19 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     record_t *rec = NULL;
     unsigned *max;
 
+    if (tag2idx[tag] == -1) {
+        LOG_Log(LOG_ALERT, "Read unexpected tag %s, DATA DISCARDED: [%.*s]",
+            VSL_tags[tag], len, ptr);
+        wrong_tags++;
+        return;
+    }
+    
     switch (tag) {
     case SLT_BackendReuse:
     case SLT_BackendClose:
         lp->state = DATA_DONE;
     case SLT_BackendOpen:
+    case SLT_BackendXID:
     case SLT_TxRequest:
     case SLT_TxURL:
     case SLT_RxStatus:
@@ -280,14 +302,17 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     case SLT_Fetch_Body:
         if (!lp->spec)
             lp->spec = VSL_S_BACKEND;
-        else
-            assert(lp->spec == VSL_S_BACKEND);
+        else if (lp->spec != VSL_S_BACKEND) {
+            spec_mismatch(tag, VSL_S_BACKEND, lp->spec, ptr, len);
+            return;
+        }
         break;
         
     case SLT_ReqEnd:
     case SLT_SessionClose:
     case SLT_StatSess:
         lp->state = DATA_DONE;
+    case SLT_SessionOpen:
     case SLT_ReqStart:
     case SLT_RxRequest:
     case SLT_RxURL:
@@ -298,8 +323,10 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     case SLT_FetchError:
         if (!lp->spec)
             lp->spec = VSL_S_CLIENT;
-        else
-            assert(lp->spec == VSL_S_CLIENT);
+        else if (lp->spec != VSL_S_CLIENT) {
+            spec_mismatch(tag, VSL_S_CLIENT, lp->spec, ptr, len);
+            return;
+        }
         break;
 
     default:
@@ -309,8 +336,10 @@ collect(struct logline_t *lp, enum VSL_tag_e tag, unsigned spec,
     if (spec & VSL_S_BACKEND || spec & VSL_S_CLIENT) {
         if (!lp->spec)
             lp->spec = spec;
-        else
-            assert(lp->spec == spec);
+        else if (lp->spec != spec) {
+            spec_mismatch(tag, spec, lp->spec, ptr, len);
+            return;
+        }
     }
 
     if (lp->spec && !(lp->spec & cb_flag))