vmod_vtc: Add generation of arbitrary log lines

vmod/tests/vtc_b00000.vtc

+varnishtest "Test vtc.vsl()"
+
+varnish v1 -vcl {
+	import vtc;
+
+	backend proforma none;
+
+	sub vcl_init {
+		# Fake a minimal session log
+		vtc.vsl(9000, "Begin", c, "sess 0 HTTP/1");
+		vtc.vsl(9000, "SessOpen", c, "127.0.0.1 123 a0 127.0.0.1 124 1643281288.313845 22");
+		vtc.vsl(9000, "Link", c, "req 9001 rxreq");
+		vtc.vsl(9001, "Begin", c, "req 9000 rxreq");
+		vtc.vsl(9001, "End", c, "");
+		vtc.vsl(9000, "End", c, "");
+
+		vtc.vsl_replay("""
+**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
+**** v1    vsl|       1000 SessOpen        c 127.0.0.1 53112 a0 127.0.0.1 37263 1643285160.270383 22
+**** v1    vsl|       1000 Link            c req 1001 rxreq
+**** v1    vsl|       1001 Begin           c req 1000 rxreq
+**** v1    vsl|       1001 Timestamp       c Start: 1643285160.271226 0.000000 0.000000
+**** v1    vsl|       1001 Timestamp       c Req: 1643285160.271226 0.000000 0.000000
+**** v1    vsl|       1001 VCL_use         c vcl1
+**** v1    vsl|       1001 ReqStart        c 127.0.0.1 53112 a0
+**** v1    vsl|       1001 ReqMethod       c GET
+**** v1    vsl|       1001 ReqURL          c /
+**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
+**** v1    vsl|       1001 ReqHeader       c Pattern: /foo/
+**** v1    vsl|       1001 ReqHeader       c Subject: /foo/
+**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
+**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
+**** v1    vsl|       1001 VCL_call        c RECV
+**** v1    vsl|       1001 VCL_return      c synth
+**** v1    vsl|       1001 VCL_call        c HASH
+**** v1    vsl|       1001 VCL_return      c lookup
+**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
+**** v1    vsl|       1001 RespStatus      c 200
+**** v1    vsl|       1001 RespReason      c OK
+**** v1    vsl|       1001 RespHeader      c Date: Thu, 27 Jan 2022 12:06:00 GMT
+**** v1    vsl|       1001 RespHeader      c Server: Varnish
+**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
+**** v1    vsl|       1001 VCL_call        c SYNTH
+**** v1    vsl|       1001 RespHeader      c Match: true
+**** v1    vsl|       1001 RespHeader      c Match-Nopathname: true
+**** v1    vsl|       1001 RespHeader      c Match-Noescape: true
+**** v1    vsl|       1001 RespHeader      c Match-Period: true
+**** v1    vsl|       1001 RespHeader      c Content-Type: text/html; charset=utf-8
+**** v1    vsl|       1001 RespHeader      c Retry-After: 5
+**** v1    vsl|       1001 VCL_return      c deliver
+**** v1    vsl|       1001 Timestamp       c Process: 1643285160.271421 0.000195 0.000195
+**** v1    vsl|       1001 RespHeader      c Content-Length: 227
+**** v1    vsl|       1001 Storage         c malloc Transient
+**** v1    vsl|       1001 Filters         c 
+**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
+**** v1    vsl|       1001 Timestamp       c Resp: 1643285160.271493 0.000267 0.000072
+**** v1    vsl|       1001 ReqAcct         c 67 0 67 270 227 497
+**** v1    vsl|       1001 End             c 
+**** v1    vsl|       1000 SessClose       c REM_CLOSE 0.009
+**** v1    vsl|       1000 End             c 
+""");
+	}
+} -start
+
+logexpect l1 -v v1 -d 1 -g vxid {
+	expect * 9000 Begin sess
+	expect 5 9000 End
+} -run
+
+logexpect l2 -v v1 -d 1 -g session -q "SessOpen ~ 53112" {
+	expect * 1000 Begin sess
+	expect * 1001 Begin req
+	expect *    = RespHeader Connection:
+} -run

vmod/vmod_vtc.c

@@ -31,6 +31,7 @@
 
 #include "config.h"
 
+#include <stdlib.h>
 #include <stdio.h>
 #include <string.h>
 #include <unistd.h>
@@ -362,3 +363,161 @@ vmod_proxy_header(VRT_CTX, VCL_ENUM venum, VCL_IP client, VCL_IP server,
 	return (VRT_blob(ctx, "proxy_header", h, l,
 	    BLOB_VMOD_PROXY_HEADER_TYPE));
 }
+
+// ref vsl.c
+struct vsl_tag2enum {
+	const char	*string;
+	enum VSL_tag_e	tag;
+};
+
+static struct vsl_tag2enum vsl_tag2enum[SLT__MAX] = {
+#define SLTM(name,flags,sdesc,ldesc) [SLT_ ## name] = {	\
+		.string = #name,				\
+		.tag = SLT_ ## name				\
+	},
+#include "tbl/vsl_tags.h"
+};
+
+static int
+vsl_tagcmp(const void *aa, const void *bb)
+{
+	const struct vsl_tag2enum *a = aa, *b = bb;
+
+	// ref vsl2rst.c ptag_cmp
+	if (a->string == NULL && b->string != NULL)
+		return (1);
+	else if (a->string != NULL && b->string == NULL)
+		return (-1);
+	else if (a->string == NULL && b->string == NULL)
+		return (0);
+	return (strcmp(a->string, b->string));
+}
+
+/*lint -esym(528, init_vsl_tag2enum) */
+static void __attribute__((constructor))
+init_vsl_tag2enum(void)
+{
+	qsort(vsl_tag2enum, SLT__MAX, sizeof *vsl_tag2enum, vsl_tagcmp);
+}
+
+
+VCL_VOID
+vmod_vsl(VRT_CTX, VCL_INT id, VCL_STRING tag_s, VCL_ENUM side, VCL_STRANDS s)
+{
+	struct vsl_tag2enum *te, key;
+	uint32_t vxid;
+
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+
+	key.string = tag_s;
+	te = bsearch(&key, vsl_tag2enum, SLT__MAX,
+	    sizeof *vsl_tag2enum, vsl_tagcmp);
+
+	if (te == NULL) {
+		VRT_fail(ctx, "No such tag: %s", tag_s);
+		return;
+	}
+
+	if (id < 0 || id > VSL_IDENTMASK) {
+		VRT_fail(ctx, "id out of bounds");
+		return;
+	}
+
+	vxid = id & VSL_IDENTMASK;
+	if (side == VENUM(c))
+		vxid |= VSL_CLIENTMARKER;
+	else if (side == VENUM(b))
+		vxid |= VSL_BACKENDMARKER;
+	else
+		WRONG("side");
+
+	VSLs(te->tag, vxid, s);
+}
+
+static void
+vsl_line(VRT_CTX, char *str)
+{
+	VCL_INT id;
+	VCL_ENUM side;
+	VCL_STRANDS s;
+	const char *tag, *delim = " \t\r\n";
+	char *save;
+
+	if (*str == '*') {
+		// varnishtest
+		str = strstr(str, "vsl|");
+		if (str == NULL)
+			return;
+		str += 4;
+	}
+	if ((str = strtok_r(str, delim, &save)) == NULL)
+		return;
+	id = strtoll(str, NULL, 10);
+
+	if ((str = strtok_r(NULL, delim, &save)) == NULL)
+		return;
+	tag = str;
+
+	if ((str = strtok_r(NULL, delim, &save)) == NULL)
+		return;
+	if (*str == 'c')
+		side = VENUM(c);
+	else if (*str == 'b')
+		side = VENUM(b);
+	else
+		return;
+
+	str = strtok_r(NULL, "\r\n", &save);
+	if (str == NULL)
+		s = vrt_null_strands;
+	else
+		s = TOSTRAND(str);
+
+	vmod_vsl(ctx, id, tag, side, s);
+}
+
+VCL_VOID
+vmod_vsl_replay(VRT_CTX, VCL_STRANDS s)
+{
+	struct vsb cp[1];
+	const char *p, *pp;
+	size_t l;
+	int i, err = 0;
+
+	if (s == NULL || s->n == 0)
+		return;
+
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+	CHECK_OBJ_NOTNULL(ctx->ws, WS_MAGIC);
+	WS_VSB_new(cp, ctx->ws);
+
+	for (i = 0; i < s->n; i++) {
+		p = s->p[i];
+		if (p == NULL || *p == '\0')
+			continue;
+		pp = strpbrk(p, "\r\n");
+		while (pp != NULL) {
+			l = pp - p;
+			if (VSB_bcat(cp, p, l) || VSB_finish(cp)) {
+				err = 1;
+				break;
+			}
+			vsl_line(ctx, VSB_data(cp));
+			VSB_clear(cp);
+			p = pp + 1;
+			pp = strpbrk(p, "\r\n");
+		}
+		if (err || VSB_cat(cp, p)) {
+			err = 1;
+			break;
+		}
+	}
+	if (err || VSB_finish(cp)) {
+		AZ(WS_VSB_finish(cp, ctx->ws, NULL));
+		VRT_fail(ctx, "out of workspace");
+		return;
+	}
+	vsl_line(ctx, VSB_data(cp));
+	VSB_clear(cp);
+	AN(WS_VSB_finish(cp, ctx->ws, NULL));
+}

vmod/vmod_vtc.vcc

@@ -169,6 +169,30 @@ version ``v1``).
 Candidate for moving into vmod_proxy, but there were concerns about
 the interface design
 
+VSL
+===
+
+These functions allow to generate arbitrary log entries to test the
+Varnish Shared Log (VSL) implementation and readers like varnishlog.
+
+$Function VOID vsl(INT vxid, STRING tag, ENUM { c, b } side, STRANDS s)
+
+Call ``VSLs()`` with the given parameters.
+
+The argument order is chosen to match VSL output.
+
+A VCL error is triggered if `tag` can not be resolved at runtime or
+if vxid is out of bounds.
+
+$Function VOID vsl_replay(STRANDS s)
+
+Replay literal log lines.
+
+The parser accepts the output generated by ``varnishlog -g raw`` and
+varnishtest log ``vsl|`` lines.
+
+Unparsable lines are silently ignored.
+
 SEE ALSO
 ========