Formatters now search for the first tag and/or header in a transaction

that are needed for the format, rather than the last. This is necessary
because Varnish 4.0.x logs are still mixing the URLs and headers of
ESI-included requests into the same log transaction, so that we were
getting the URL/headers of the last ESI include, rather than those
of the root request.

src/format.c

@@ -108,64 +108,56 @@ get_payload(const rec_t *rec)
 }
 
 /*
- * Return the *last* record in tx that matches the tag
+ * Return the *first* record in tx that matches the tag, or NULL if none
+ * match
  */
 rec_t *
 get_tag(const tx_t *tx, enum VSL_tag_e tag)
 {
-    rec_t *rec, *tagrec = NULL;
+    rec_t *rec;
 
     CHECK_OBJ_NOTNULL(tx, TX_MAGIC);
     VSTAILQ_FOREACH(rec, &tx->recs, reclist) {
         CHECK_OBJ_NOTNULL(rec, RECORD_MAGIC);
         assert(OCCUPIED(rec));
         if (rec->tag == tag)
-            tagrec = rec;
+            return rec;
     }
-    return tagrec;
+    return NULL;
 }
 
 /*
- * Return the header payload of the *last* record in tx that matches the
+ * Return the header payload of the *first* record in tx that matches the
  * tag and the header name.
  */
 char *
 get_hdr(const tx_t *tx, enum VSL_tag_e tag, const char *hdr)
 {
     rec_t *rec;
-    char *hdr_payload = NULL;
 
     CHECK_OBJ_NOTNULL(tx, TX_MAGIC);
     VSTAILQ_FOREACH(rec, &tx->recs, reclist) {
-        char *c, *h;
+        char *c;
 
         CHECK_OBJ_NOTNULL(rec, RECORD_MAGIC);
         assert(OCCUPIED(rec));
         if (rec->tag != tag)
             continue;
         c = get_payload(rec);
-        h = c;
-        while (isspace(*h))
-            h++;
-        if (strncasecmp(h, hdr, strlen(hdr)) != 0)
+        while (isspace(*c))
+            c++;
+        if (strncasecmp(c, hdr, strlen(hdr)) != 0)
             continue;
-        h += strlen(hdr);
-        while (isspace(*h))
-            h++;
-        if (*h++ != ':')
+        c += strlen(hdr);
+        while (isspace(*c))
+            c++;
+        if (*c++ != ':')
             continue;
-        while (isspace(*h))
-            h++;
-        if (rec->len <= config.chunk_size)
-            hdr_payload = h;
-        else {
-            VSB_clear(hdr_sb);
-            VSB_bcpy(hdr_sb, h, rec->len - (h - c));
-            VSB_finish(hdr_sb);
-            hdr_payload = VSB_data(hdr_sb);
-        }
+        while (isspace(*c))
+            c++;
+        return c;
     }
-    return hdr_payload;
+    return NULL;
 }
 
 /*

src/test/regress.sh

@@ -12,7 +12,7 @@ rm -f $LOG $OUT
 ../varnishevent -f varnishevent.conf -r sw-doc.log -w $OUT -v
 
 CKSUM=$( cksum $OUT )
-if [ "$CKSUM" != "1773971926 22636057 $OUT" ]; then
+if [ "$CKSUM" != "953184597 22701157 $OUT" ]; then
     echo "ERROR: Regression test log output incorrect cksum: $CKSUM"
     exit 1
 fi

src/test/test_format.c

@@ -189,7 +189,7 @@ static const char
     recs[NRECORDS / 2].tag = SLT_RespHeader;
     recs[NRECORDS - 1].tag = SLT_RespHeader;
     rec = get_tag(&tx, SLT_RespHeader);
-    MASSERT(rec == &recs[NRECORDS - 1]);
+    MASSERT(rec == &recs[NRECORDS / 2]);
 
     /* Record not found */
     recs[NRECORDS / 2].tag = SLT_ReqHeader;
@@ -238,19 +238,19 @@ static const char
     strcpy(c[NRECORDS - 1].data, "Foo: wilco");
     hdr = get_hdr(&tx, SLT_ReqHeader, "Foo");
     MAN(hdr);
-    MASSERT(strcmp(hdr, "wilco") == 0);
+    MASSERT(strcmp(hdr, "quux") == 0);
 
     /* Case-insensitive match */
     hdr = get_hdr(&tx, SLT_ReqHeader, "fOO");
     MAN(hdr);
-    MASSERT(strcmp(hdr, "wilco") == 0);
+    MASSERT(strcmp(hdr, "quux") == 0);
 
     /* Ignore whitespace  */
-    recs[NRECORDS - 1].len = strlen("  Foo  :  wilco");
-    strcpy(c[NRECORDS - 1].data, "  Foo  :  wilco");
+    recs[NRECORDS / 2].len = strlen("  Foo  :  quux");
+    strcpy(c[NRECORDS / 2].data, "  Foo  :  quux");
     hdr = get_hdr(&tx, SLT_ReqHeader, "Foo");
     MAN(hdr);
-    MASSERT(strcmp(hdr, "wilco") == 0);
+    MASSERT(strcmp(hdr, "quux") == 0);
 
     /* Different headers after the matching header */
     hdr = get_hdr(&tx, SLT_ReqHeader, "Bar");
@@ -1566,7 +1566,7 @@ static const char
     VSB_finish(os);
 #define EXP_FULL_CLIENT_OUTPUT "105 c 15963 HTTP/1.1 127.0.0.1 60 foohdr "\
         "barhdr - GET 283 bar=baz&quux=wilco GET "\
-        "http://bazquux.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
+        "http://foobar.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
         "[%d/%b/%Y:%T %z] 0 %F-%T.529143 /foo varnish 0.000166 hit hit "\
         "logload MATCH ACL \"10.0.0.0\"/8 \"foo\\0\\377 bar\" " \
         "1429213569.602005 0.000000 0.000000 60 0.000125 4711 1147\n"
@@ -1640,7 +1640,7 @@ static const char
     VSB_finish(os);
 #define EXP_FULL_BACKEND_OUTPUT "105 b 15703 HTTP/1.1 default(127.0.0.1,,80) "\
         "283 foohdr barhdr - GET 60 bar=baz&quux=wilco GET "\
-        "http://bazquux.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
+        "http://foobar.com/foo?bar=baz&quux=wilco HTTP/1.1 200 "\
         "[%d/%b/%Y:%T %z] 0 %F-%T.529143 /foo varnish 0.002837 logload "\
         "2 chunked stream \"foo\\0\\377 bar\" "\
         "1429210777.728290 0.000048 0.000048 283 0.000048 4711 1147\n"

src/test/vslarg.sh

@@ -11,7 +11,7 @@ echo "... -g vxid"
 CKSUM=$( ../varnishevent -g vxid -r sw-doc.log -f varnishevent.conf | cksum)
 
 # Same as default (no -g arg)
-if [ "$CKSUM" != '1162093504 22636095' ]; then
+if [ "$CKSUM" != '3954993142 22701195' ]; then
     echo "ERROR: -g vxid unexpected cksum: $CKSUM"
     exit 1
 fi
@@ -19,7 +19,7 @@ fi
 echo "... -g request"
 CKSUM=$( ../varnishevent -g request -r sw-doc.log -f varnishevent.conf | cksum)
 
-if [ "$CKSUM" != '2524911127 22637823' ]; then
+if [ "$CKSUM" != '3202005014 22702923' ]; then
     echo "ERROR: -g request unexpected cksum: $CKSUM"
     exit 1
 fi