Add record-prefix support to varnishncsa

The parsing still requires some TLC but this does not make it any
worse so let's get this in first.

Prompted by and ideas from github::xcir via #2077.

bin/varnishncsa/varnishncsa.c

@@ -130,6 +130,8 @@ struct vsl_watch {
 	VTAILQ_ENTRY(vsl_watch)	list;
 	enum VSL_tag_e		tag;
 	int			idx;
+	char			*prefix;
+	int			prefixlen;
 	struct fragment		frag;
 };
 VTAILQ_HEAD(vsl_watch_head, vsl_watch);
@@ -567,7 +569,7 @@ addf_hdr(struct watch_head *head, const char *key, const char *str)
 }
 
 static void
-addf_vsl(enum VSL_tag_e tag, long i)
+addf_vsl(enum VSL_tag_e tag, long i, const char *prefix)
 {
 	struct vsl_watch *w;
 
@@ -576,6 +578,10 @@ addf_vsl(enum VSL_tag_e tag, long i)
 	w->tag = tag;
 	assert(i <= INT_MAX);
 	w->idx = i;
+	if (prefix) {
+		assert(asprintf(&w->prefix, "%s:", prefix) > 0);
+		w->prefixlen = strlen(w->prefix);
+	}
 	VTAILQ_INSERT_TAIL(&CTX.watch_vsl, w, list);
 
 	addf_fragment(&w->frag, "-");
@@ -658,14 +664,23 @@ parse_x_format(char *buf)
 			*r = '\0';
 		} else
 			i = 0;
-		slt = VSL_Name2Tag(buf, -1);
+		r = buf;
+		while (r < e && *r != ':')
+			r++;
+		if (r != e) {
+			slt = VSL_Name2Tag(buf, r - buf);
+			r++;
+		} else {
+			slt = VSL_Name2Tag(buf, -1);
+			r = NULL;
+		}
 		if (slt == -2)
 			VUT_Error(1, "Tag not unique: %s", buf);
 		if (slt == -1)
 			VUT_Error(1, "Unknown log tag: %s", buf);
 		assert(slt >= 0);
 
-		addf_vsl(slt, i);
+		addf_vsl(slt, i, r);
 		return;
 	}
 	VUT_Error(1, "Unknown formatting extension: %s", buf);
@@ -902,15 +917,20 @@ process_vsl(const struct vsl_watch_head *head, enum VSL_tag_e tag,
     const char *b, const char *e)
 {
 	struct vsl_watch *w;
+	const char *p;
 
 	VTAILQ_FOREACH(w, head, list) {
 		CHECK_OBJ_NOTNULL(w, VSL_WATCH_MAGIC);
 		if (tag != w->tag)
 			continue;
+		p = b;
+		if (w->prefixlen > 0 &&
+		    !isprefix(w->prefix, w->prefixlen, b, e, &p))
+			continue;
 		if (w->idx == 0)
-			frag_line(0, b, e, &w->frag);
+			frag_line(0, p, e, &w->frag);
 		else
-			frag_fields(0, b, e, w->idx, &w->frag, 0, NULL);
+			frag_fields(0, p, e, w->idx, &w->frag, 0, NULL);
 	}
 }
 
@@ -1091,7 +1111,7 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 			    (tag == SLT_BerespHeader && CTX.b_opt))
 				process_hdr(&CTX.watch_resphdr, b, e);
 
-			process_vsl(&CTX.watch_vsl, tag, b ,e);
+			process_vsl(&CTX.watch_vsl, tag, b, e);
 		}
 		if (skip)
 			continue;

bin/varnishtest/tests/u00003.vtc

@@ -9,6 +9,30 @@ varnish v1 -vcl+backend {} -start
 
 shell "varnishncsa -n ${v1_name} -D -P ${tmpdir}/ncsa.pid -w ${tmpdir}/ncsa.log"
 
+delay 1
+
+client c1 {
+	txreq -url /foo
+	rxresp
+} -run
+
+delay 1
+
+shell "mv ${tmpdir}/ncsa.log ${tmpdir}/ncsa.old.log"
+shell "kill -HUP `cat ${tmpdir}/ncsa.pid`"
+
+client c1 {
+	txreq -url /bar
+	rxresp
+} -run
+
+delay 1
+
+shell "kill `cat ${tmpdir}/ncsa.pid`"
+
+shell "grep -q /foo ${tmpdir}/ncsa.old.log"
+shell "grep -q /bar ${tmpdir}/ncsa.log"
+
 shell -expect "Usage: varnishncsa <options>" \
 	"varnishncsa -h"
 shell -expect "Copyright (c) 2006 Verdens Gang AS" \
@@ -50,30 +74,10 @@ shell -err -expect "Empty format file" \
 #shell -err -expect "Can't read format from file (Is a directory)" \
 #	{varnishncsa -f ${tmpdir}}
 
-delay 1
-
-client c1 {
-	txreq -url /foo
-	rxresp
-} -run
-
-delay 1
-
-shell "mv ${tmpdir}/ncsa.log ${tmpdir}/ncsa.old.log >/dev/null 2>&1"
-shell "kill -HUP `cat ${tmpdir}/ncsa.pid`"
-
-client c1 {
-	txreq -url /bar
-	rxresp
-} -run
-
-delay 1
-
-shell "kill `cat ${tmpdir}/ncsa.pid`"
-
-shell "grep -q /foo ${tmpdir}/ncsa.old.log"
-shell "grep -q /bar ${tmpdir}/ncsa.log"
-
-shell {echo "%{VSL:Begin}x %{Varnish:vxid}x %D %T %{Varnish:handling}x %{%Z}t" >${tmpdir}/format}
-shell -match "req 1000 rxreq 1001 [0-9]{5} 0 miss [A-Z]{3,}" \
+shell {echo "%{VSL:Begin}x %{Varnish:vxid}x %{VCL_Log:foo}x %D %T %{Varnish:handling}x %{%Z}t" >${tmpdir}/format}
+shell -match "^req 1000 rxreq 1001  [0-9]+ 0 miss [A-Z]{3,}" \
 	{varnishncsa -n ${v1_name} -d -f ${tmpdir}/format}
+shell -match "^bereq 1001 fetch 1002  [0-9]+ 0 - [A-Z]{3,}" \
+	{varnishncsa -n ${v1_name} -d -f ${tmpdir}/format -b}
+shell -match "\d{10}\.\d{6} \d\.\d{6} \d\.\d{6} - \d{10}\.\d{6}" \
+	{varnishncsa -n ${v1_name} -d -F "%{VSL:Timestamp:Resp}x %{VSL:Timestamp:foo}x %{VSL:Timestamp:Resp[2]}x"}

doc/sphinx/reference/varnishncsa.rst

@@ -174,13 +174,22 @@ Supported formatters are:
   VCL_Log:key
     Output value set by std.log("key:value") in VCL.
 
-  VSL:tag[field]
-    The value of the VSL entry for the given tag. The field will,
-    if present, treat the log record as a white space separated list
-    of fields, and only the nth part of the record will be matched
-    against. Fields start counting at 1. Defaults to '-' when the tag
-    is not seen, or when the field is out of bounds. If a tag appears
-    multiple times in a single transaction, the first occurrence is used.
+  VSL:tag:record-prefix[field]
+    The value of the VSL entry for the given tag-record prefix-field
+    combination. Tag is mandatory, the other components are optional.
+
+    The record prefix will limit the matches to those records that
+    have this prefix as the first part of the record content followed
+    by a colon.
+
+    The field will, if present, treat the log record as a white
+    space separated list of fields, and only the nth part of the
+    record will be matched against. Fields start counting at 1.
+
+    Defaults to '-' when the tag is not seen, the record prefix
+    does not match or the field is out of bounds. If a tag appears
+    multiple times in a single transaction, the first occurrence
+    is used.
 
 SIGNALS
 =======
@@ -202,11 +211,15 @@ multiple times in a single transaction, the first occurrence is used.
 EXAMPLE
 =======
 
-Log the second field of the Begin tag, corresponding to the VXID of the
-parent transaction::
+Log the second field of the Begin record, corresponding to the VXID
+of the parent transaction::
 
   varnishncsa -F "%{VSL:Begin[2]}x"
 
+Log the entire Timestamp record associated with the processing length::
+
+  varnishncsa -F "%{VSL:Timestamp:Process}x"
+
 SEE ALSO
 ========