vsl: Apply VSL_OPT_E to the Begin[4] field

As I was relying on the lack of -E option to discard another type of
non-ESI sub-requests I recently misled myself with this assumption. It
took me a while to realize that I was also seeing transactions I was not
interested in, corrupting the statistics I was deriving from a log dump.

Now that vmod_pesi [1] sets the precedent, we should expect new types of
sub-requests to materialize and expecting the reason for the transaction
to be "esi" is no longer appropriate.

We could also track this field as vtx::sub_level for example, to make it
available as VSL query LHS operand. The focus here was to adjust the
behavior of an existing feature, not add a new one.

[1] https://code.uplex.de/uplex-varnish/libvdp-pesi

bin/varnishtest/tests/l00007.vtc

+varnishtest "Begin[4] and VSL_OPT_E"
+
+varnish v1 -vcl {
+	import vtc;
+
+	backend be none;
+
+	sub vcl_init {
+		# make up a replay with -i Begin,Link,End
+		vtc.vsl_replay({"
+**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
+**** v1    vsl|       1000 Link            c req 1001 rxreq
+**** v1    vsl|       1003 Begin           b bereq 1002 fetch
+**** v1    vsl|       1003 End             b
+**** v1    vsl|       1002 Begin           c req 1001 vmod_foo:subreq 1
+**** v1    vsl|       1002 End             c
+**** v1    vsl|       1001 Begin           c req 1000 rxreq
+**** v1    vsl|       1001 Link            c req 1002 vmod_foo:subreq 1
+**** v1    vsl|       1001 End             c
+**** v1    vsl|       1000 End             c
+**** v1    vsl|       1004 Begin           c sess 0 HTTP/1
+**** v1    vsl|       1004 End             c
+		"});
+	}
+} -start
+
+varnish v1 -vsl_catchup
+
+logexpect l1 -v v1 -d 1 {
+	expect 0 1003 Begin	"bereq 1002 fetch"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l1_bis -v v1 -d 1 -b 1 -c 1 {
+	expect 0 1003 Begin	"bereq 1002 fetch"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l2 -v v1 -d 1 -b 1 {
+	expect 0 1003 Begin	"bereq 1002 fetch"
+	expect 0 =    End
+} -run
+
+logexpect l3 -v v1 -d 1 -c 1 {
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l4 -v v1 -d 1 -E 1 {
+	expect 0 1002 Begin	"req 1001 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l4_bis -v v1 -d 1 -c 1 -E 1 {
+	expect 0 1002 Begin	"req 1001 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l5 -v v1 -d 1 -b 1 -E 1 {
+	expect 0 1003 Begin	"bereq 1002 fetch"
+	expect 0 =    End
+	expect 0 1002 Begin	"req 1001 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run
+
+logexpect l5_bis -v v1 -d 1 -b 1 -c 1 -E 1 {
+	expect 0 1003 Begin	"bereq 1002 fetch"
+	expect 0 =    End
+	expect 0 1002 Begin	"req 1001 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1001 Begin	"req 1000 rxreq"
+	expect 0 =    Link	"req 1002 vmod_foo:subreq"
+	expect 0 =    End
+	expect 0 1000 Begin	"sess 0 HTTP/1"
+	expect 0 =    Link	"req 1001 rxreq"
+	expect 0 =    End
+	expect 0 1004 Begin	"sess 0 HTTP/1"
+	expect 0 =    End
+} -run

include/vapi/vapi_options.h

@@ -54,7 +54,9 @@
 
 #define VSL_OPT_E							\
 	VOPT("E", "[-E]", "Display ESI transactions",			\
-	    "Display ESI transactions and other client transactions."	\
+	    "Display ESI transactions and other types of sub-requests."	\
+	    " This implies the -c option and includes other client"	\
+	    " transactions."						\
 	)
 
 #define VSL_OPT_i							\

lib/libvarnishapi/vsl.c

@@ -190,10 +190,12 @@ VSL_Match(struct VSL_data *vsl, const struct VSL_cursor *c)
 	tag = VSL_TAG(c->rec.ptr);
 	if (tag <= SLT__Bogus || tag >= SLT__Reserved)
 		return (0);
-	if (vsl->c_opt && !VSL_CLIENT(c->rec.ptr))
-		return (0);
-	if (vsl->b_opt && !VSL_BACKEND(c->rec.ptr))
-		return (0);
+	if (!vsl->c_opt || !vsl->b_opt) {
+		if (vsl->c_opt && !VSL_CLIENT(c->rec.ptr))
+			return (0);
+		if (vsl->b_opt && !VSL_BACKEND(c->rec.ptr))
+			return (0);
+	}
 	if (!VTAILQ_EMPTY(&vsl->vslf_select) &&
 	    vsl_match_IX(vsl, &vsl->vslf_select, c))
 		return (1);

lib/libvarnishapi/vsl_dispatch.c

@@ -689,10 +689,10 @@ vtx_set_parent(struct vtx *parent, struct vtx *child)
    successfully parsed. */
 static int
 vtx_parse_link(const char *str, enum VSL_transaction_e *ptype,
-    unsigned *pvxid, enum VSL_reason_e *preason)
+    unsigned *pvxid, enum VSL_reason_e *preason, unsigned *psub)
 {
 	char type[16], reason[16];
-	unsigned vxid;
+	unsigned vxid, sub;
 	int i;
 	enum VSL_transaction_e et;
 	enum VSL_reason_e er;
@@ -702,7 +702,7 @@ vtx_parse_link(const char *str, enum VSL_transaction_e *ptype,
 	AN(pvxid);
 	AN(preason);
 
-	i = sscanf(str, "%15s %u %15s", type, &vxid, reason);
+	i = sscanf(str, "%15s %u %15s %u", type, &vxid, reason, &sub);
 	if (i < 1)
 		return (0);
 
@@ -729,7 +729,13 @@ vtx_parse_link(const char *str, enum VSL_transaction_e *ptype,
 	if (er >= VSL_r__MAX)
 		er = VSL_r_unknown;
 	*preason = er;
-	return (3);
+	if (i == 3)
+		return (3);
+
+	/* request sub-level */
+	if (psub != NULL)
+		*psub = sub;
+	return (4);
 }
 
 /* Parse and process a begin record */
@@ -746,8 +752,8 @@ vtx_scan_begin(struct VSLQ *vslq, struct vtx *vtx, const uint32_t *ptr)
 
 	AZ(vtx->flags & VTX_F_READY);
 
-	i = vtx_parse_link(VSL_CDATA(ptr), &type, &p_vxid, &reason);
-	if (i != 3)
+	i = vtx_parse_link(VSL_CDATA(ptr), &type, &p_vxid, &reason, NULL);
+	if (i < 3)
 		return (vtx_diag_tag(vtx, ptr, "parse error"));
 	if (type == VSL_t_unknown)
 		(void)vtx_diag_tag(vtx, ptr, "unknown vxid type");
@@ -813,8 +819,8 @@ vtx_scan_link(struct VSLQ *vslq, struct vtx *vtx, const uint32_t *ptr)
 
 	AZ(vtx->flags & VTX_F_READY);
 
-	i = vtx_parse_link(VSL_CDATA(ptr), &c_type, &c_vxid, &c_reason);
-	if (i != 3)
+	i = vtx_parse_link(VSL_CDATA(ptr), &c_type, &c_vxid, &c_reason, NULL);
+	if (i < 3)
 		return (vtx_diag_tag(vtx, ptr, "parse error"));
 	if (c_type == VSL_t_unknown)
 		(void)vtx_diag_tag(vtx, ptr, "unknown vxid type");
@@ -1288,7 +1294,7 @@ vslq_candidate(struct VSLQ *vslq, const uint32_t *ptr)
 	enum VSL_reason_e reason;
 	struct VSL_data *vsl;
 	enum VSL_tag_e tag;
-	unsigned p_vxid;
+	unsigned p_vxid, sub;
 	int i;
 
 	CHECK_OBJ_NOTNULL(vslq, VSLQ_MAGIC);
@@ -1302,24 +1308,24 @@ vslq_candidate(struct VSLQ *vslq, const uint32_t *ptr)
 	CHECK_OBJ_NOTNULL(vsl, VSL_MAGIC);
 	if (vslq->grouping == VSL_g_vxid) {
 		if (!vsl->c_opt && !vsl->b_opt)
-			return (1); /* Implies also !vsl->E_opt */
-		if (!vsl->b_opt && !VSL_CLIENT(ptr))
+			AZ(vsl->E_opt);
+		else if (!vsl->b_opt && !VSL_CLIENT(ptr))
 			return (0);
-		if (!vsl->c_opt && !VSL_BACKEND(ptr))
+		else if (!vsl->c_opt && !VSL_BACKEND(ptr))
 			return (0);
 		/* Need to parse the Begin tag - fallthrough to below */
 	}
 
 	tag = VSL_TAG(ptr);
 	assert(tag == SLT_Begin);
-	i = vtx_parse_link(VSL_CDATA(ptr), &type, &p_vxid, &reason);
-	if (i != 3 || type == VSL_t_unknown)
+	i = vtx_parse_link(VSL_CDATA(ptr), &type, &p_vxid, &reason, &sub);
+	if (i < 3 || type == VSL_t_unknown)
 		return (0);
 
-	if (type == VSL_t_sess)
+	if (vslq->grouping == VSL_g_request && type == VSL_t_sess)
 		return (0);
 
-	if (vslq->grouping == VSL_g_vxid && reason == VSL_r_esi && !vsl->E_opt)
+	if (vslq->grouping == VSL_g_vxid && i > 3 && sub > 0 && !vsl->E_opt)
 		return (0);
 
 	return (1);