[master] e8eac09 Clean up the vtc_logging a little bit, and make a explicit vtc_fatal() function to use instead of vtc_log(..., 0, ) in trivial cases.

Poul-Henning Kamp phk at FreeBSD.org
Wed Jan 18 11:26:05 CET 2017


commit e8eac09fe5f709c041074d56ea95759def5cd97d
Author: Poul-Henning Kamp <phk at FreeBSD.org>
Date:   Wed Jan 18 10:24:11 2017 +0000

    Clean up the vtc_logging a little bit, and make a explicit vtc_fatal()
    function to use instead of vtc_log(..., 0,) in trivial cases.

diff --git a/bin/varnishtest/flint.lnt b/bin/varnishtest/flint.lnt
index 3c31604..1ef8431 100644
--- a/bin/varnishtest/flint.lnt
+++ b/bin/varnishtest/flint.lnt
@@ -1,6 +1,9 @@
 
-// vtc_log's arg2 acts like an assert
+// Tell FlexeLint when these don't return
+-function(exit, vtc_fatal)
 -function(__assert(1), vtc_log(2))
+-function(__assert(1), vtc_dump(2))
+-function(__assert(1), vtc_hexdump(2))
 
 -esym(850, av)
 
diff --git a/bin/varnishtest/vtc.c b/bin/varnishtest/vtc.c
index e2cb6b0..fe503b2 100644
--- a/bin/varnishtest/vtc.c
+++ b/bin/varnishtest/vtc.c
@@ -239,7 +239,7 @@ macro_expand(struct vtclog *vl, const char *text)
 		m = macro_get(p, q);
 		if (m == NULL) {
 			VSB_destroy(&vsb);
-			vtc_log(vl, 0, "Macro ${%.*s} not found", (int)(q - p),
+			vtc_fatal(vl, "Macro ${%.*s} not found", (int)(q - p),
 			    p);
 			NEEDLESS(return (NULL));
 		}
@@ -330,7 +330,7 @@ parse_string(const char *spec, const struct cmds *cmd, void *priv,
 						q++;
 					} else {
 						if (*p == '\n')
-							vtc_log(vl, 0,
+							vtc_fatal(vl,
 				"Unterminated quoted string in line: %*.*s",
 				(int)(p - f), (int)(p - f), f);
 						assert(*p != '\n');
@@ -380,7 +380,7 @@ parse_string(const char *spec, const struct cmds *cmd, void *priv,
 			if (!strcmp(token_s[0], cp->name))
 				break;
 		if (cp->name == NULL) {
-			vtc_log(vl, 0, "Unknown command: \"%s\"", token_s[0]);
+			vtc_fatal(vl, "Unknown command: \"%s\"", token_s[0]);
 			NEEDLESS(return);
 		}
 
@@ -476,7 +476,7 @@ cmd_shell_engine(struct vtclog *vl, int ok,
 	vtc_dump(vl, 4, "shell_cmd", VSB_data(vsb), -1);
 	fp = popen(VSB_data(vsb), "r");
 	if (fp == NULL)
-		vtc_log(vl, 0, "popen fails: %s", strerror(errno));
+		vtc_fatal(vl, "popen fails: %s", strerror(errno));
 	VSB_clear(vsb);
 	do {
 		c = getc(fp);
@@ -488,9 +488,9 @@ cmd_shell_engine(struct vtclog *vl, int ok,
 	if (WIFSIGNALED(r))
 		vtc_log(vl, 4, "shell_signal = %d", WTERMSIG(r));
 	if (ok < 0 && !WEXITSTATUS(r))
-		vtc_log(vl, 0, "shell did not fail as expected");
+		vtc_fatal(vl, "shell did not fail as expected");
 	else if (ok >= 0 && WEXITSTATUS(r) != ok) {
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "shell_exit not as expected: got 0x%04x wanted 0x%04x",
 			WEXITSTATUS(r), ok);
 	}
@@ -498,7 +498,7 @@ cmd_shell_engine(struct vtclog *vl, int ok,
 	vtc_dump(vl, 4, "shell_out", VSB_data(vsb), VSB_len(vsb));
 	if (expect != NULL) {
 		if (strstr(VSB_data(vsb), expect) == NULL)
-			vtc_log(vl, 0,
+			vtc_fatal(vl,
 			    "shell_expect not found: (\"%s\")", expect);
 		else
 			vtc_log(vl, 4, "shell_expect found");
@@ -680,7 +680,7 @@ cmd_feature(CMD_ARGS)
 		} else if (!strcmp(*av, "cmd")) {
 			av++;
 			if (*av == NULL) {
-				vtc_log(vl, 0, "Missing the command-line");
+				vtc_fatal(vl, "Missing the command-line");
 				return;
 			}
 			r = system(*av);
@@ -693,7 +693,7 @@ cmd_feature(CMD_ARGS)
 			continue;
 
 		if (!vtc_stop) {
-			vtc_log(vl, 0,
+			vtc_fatal(vl,
 			    "FAIL test, unknown feature: %s", *av);
 		} else {
 			vtc_log(vl, 1,
diff --git a/bin/varnishtest/vtc.h b/bin/varnishtest/vtc.h
index e196bf6..8f999ad 100644
--- a/bin/varnishtest/vtc.h
+++ b/bin/varnishtest/vtc.h
@@ -97,6 +97,8 @@ struct vtclog *vtc_logopen(const char *id);
 void vtc_logclose(struct vtclog *vl);
 void vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
     __v_printflike(3, 4);
+void vtc_fatal(struct vtclog *vl, const char *, ...)
+    __attribute__((__noreturn__)) __v_printflike(2,3);
 void vtc_dump(struct vtclog *vl, int lvl, const char *pfx,
     const char *str, int len);
 void vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
diff --git a/bin/varnishtest/vtc_barrier.c b/bin/varnishtest/vtc_barrier.c
index 4052770..04f1d71 100644
--- a/bin/varnishtest/vtc_barrier.c
+++ b/bin/varnishtest/vtc_barrier.c
@@ -78,9 +78,9 @@ barrier_new(char *name, struct vtclog *vl)
 	AN(b);
 	AN(name);
 	if (*name != 'b')
-		vtc_log(vl, 0, "Barrier name must start with 'b' (%s)", name);
+		vtc_fatal(vl, "Barrier name must start with 'b' (%s)", name);
 	if (pthread_self() != vtc_thread)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier %s can only be created on the top thread", name);
 	REPLACE(b->name, name);
 
@@ -102,14 +102,14 @@ barrier_expect(struct barrier *b, const char *av, struct vtclog *vl)
 	unsigned expected;
 
 	if (b->type != BARRIER_NONE)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: already initialized", b->name);
 
 	AZ(b->expected);
 	AZ(b->waiters);
 	expected = strtoul(av, NULL, 0);
 	if (expected < 2)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: wrong expectation (%u)",
 		    b->name, expected);
 
@@ -148,7 +148,7 @@ barrier_sock_thread(void *priv)
 	if (sock < 0) {
 		AZ(pthread_cond_signal(&b->cond));
 		AZ(pthread_mutex_unlock(&b->mtx));
-		vtc_log(vl, 0, "Barrier(%s) %s fails: %s (errno=%d)",
+		vtc_fatal(vl, "Barrier(%s) %s fails: %s (errno=%d)",
 		    b->name, err, strerror(errno), errno);
 	}
 	assert(sock > 0);
@@ -178,14 +178,14 @@ barrier_sock_thread(void *priv)
 			if (errno == EINTR)
 				continue;
 			AZ(close(sock));
-			vtc_log(vl, 0,
+			vtc_fatal(vl,
 			    "Barrier(%s) select fails: %s (errno=%d)",
 			    b->name, strerror(errno), errno);
 		}
 		assert(i == 1);
 		assert(b->waiters <= b->expected);
 		if (b->waiters == b->expected)
-			vtc_log(vl, 0,
+			vtc_fatal(vl,
 			    "Barrier(%s) use error: "
 			    "more waiters than the %u expected",
 			    b->name, b->expected);
@@ -193,7 +193,7 @@ barrier_sock_thread(void *priv)
 		i = accept(sock, NULL, NULL);
 		if (i < 0) {
 			AZ(close(sock));
-			vtc_log(vl, 0,
+			vtc_fatal(vl,
 			    "Barrier(%s) accept fails: %s (errno=%d)",
 			    b->name, strerror(errno), errno);
 		}
@@ -251,11 +251,11 @@ barrier_cyclic(struct barrier *b, struct vtclog *vl)
 	CHECK_OBJ_NOTNULL(b, BARRIER_MAGIC);
 
 	if (b->type == BARRIER_NONE)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: not initialized", b->name);
 
 	if (b->waiters != 0)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: already in use", b->name);
 
 	b->cyclic = 1;
@@ -274,7 +274,7 @@ barrier_cond_sync(struct barrier *b, struct vtclog *vl)
 
 	assert(b->waiters <= b->expected);
 	if (b->waiters == b->expected)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: more waiters than the %u expected",
 		    b->name, b->expected);
 
@@ -311,7 +311,7 @@ barrier_sock_sync(struct barrier *b, struct vtclog *vl)
 
 	sock = VTCP_open(VSB_data(vsb), NULL, 0., &err);
 	if (sock < 0)
-		vtc_log(vl, 0, "Barrier(%s) connection failed: %s",
+		vtc_fatal(vl, "Barrier(%s) connection failed: %s",
 		    b->name, err);
 
 	VSB_delete(vsb);
@@ -325,10 +325,10 @@ barrier_sock_sync(struct barrier *b, struct vtclog *vl)
 	AZ(close(sock));
 
 	if (sz < 0)
-		vtc_log(vl, 0, "Barrier(%s) read failed: %s (errno=%d)",
+		vtc_fatal(vl, "Barrier(%s) read failed: %s (errno=%d)",
 		    b->name, strerror(i), i);
 	if (sz > 0)
-		vtc_log(vl, 0, "Barrier(%s) unexpected data (%zdB)",
+		vtc_fatal(vl, "Barrier(%s) unexpected data (%zdB)",
 		    b->name, sz);
 }
 
@@ -340,7 +340,7 @@ barrier_sync(struct barrier *b, struct vtclog *vl)
 
 	switch (b->type) {
 	case BARRIER_NONE:
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Barrier(%s) use error: not initialized", b->name);
 		break;
 	case BARRIER_COND:
@@ -465,7 +465,7 @@ cmd_barrier(CMD_ARGS)
 			barrier_cyclic(b, vl);
 			continue;
 		}
-		vtc_log(vl, 0, "Unknown barrier argument: %s", *av);
+		vtc_fatal(vl, "Unknown barrier argument: %s", *av);
 	}
 	AZ(pthread_mutex_unlock(&b->mtx));
 }
diff --git a/bin/varnishtest/vtc_client.c b/bin/varnishtest/vtc_client.c
index 9e10019..3b7e6c8 100644
--- a/bin/varnishtest/vtc_client.c
+++ b/bin/varnishtest/vtc_client.c
@@ -93,14 +93,14 @@ client_proxy(struct vtclog *vl, int fd, int version, const char *spec)
 
 	error = VSS_resolver(p, NULL, proxy_cb, &sac, &err);
 	if (err != NULL)
-		vtc_log(vl, 0, "Could not resolve client address: %s", err);
+		vtc_fatal(vl, "Could not resolve client address: %s", err);
 	assert(error == 1);
 	error = VSS_resolver(p2, NULL, proxy_cb, &sas, &err);
 	if (err != NULL)
-		vtc_log(vl, 0, "Could not resolve server address: %s", err);
+		vtc_fatal(vl, "Could not resolve server address: %s", err);
 	assert(error == 1);
 	if (vtc_send_proxy(fd, version, sac, sas))
-		vtc_log(vl, 0, "Write failed: %s", strerror(errno));
+		vtc_fatal(vl, "Write failed: %s", strerror(errno));
 	free(p);
 	free(sac);
 	free(sas);
@@ -140,7 +140,7 @@ client_thread(void *priv)
 		vtc_log(vl, 3, "Connect to %s", VSB_data(vsb));
 		fd = VTCP_open(VSB_data(vsb), NULL, 10., &err);
 		if (fd < 0)
-			vtc_log(c->vl, 0, "Failed to open %s: %s",
+			vtc_fatal(c->vl, "Failed to open %s: %s",
 			    VSB_data(vsb), err);
 		assert(fd >= 0);
 		/* VTCP_blocking does its own checks, trust it */
@@ -176,7 +176,7 @@ client_new(const char *name)
 	c->vl = vtc_logopen(name);
 	AN(c->vl);
 	if (*c->name != 'c')
-		vtc_log(c->vl, 0, "Client name must start with 'c'");
+		vtc_fatal(c->vl, "Client name must start with 'c'");
 
 	bprintf(c->connect, "%s", "${v1_sock}");
 	VTAILQ_INSERT_TAIL(&clients, c, list);
@@ -227,7 +227,7 @@ client_wait(struct client *c)
 	vtc_log(c->vl, 2, "Waiting for client");
 	AZ(pthread_join(c->tp, &res));
 	if (res != NULL)
-		vtc_log(c->vl, 0, "Client returned \"%s\"", (char *)res);
+		vtc_fatal(c->vl, "Client returned \"%s\"", (char *)res);
 	c->tp = 0;
 	c->running = 0;
 }
@@ -323,7 +323,7 @@ cmd_client(CMD_ARGS)
 			continue;
 		}
 		if (**av == '-')
-			vtc_log(c->vl, 0, "Unknown client argument: %s", *av);
+			vtc_fatal(c->vl, "Unknown client argument: %s", *av);
 		REPLACE(c->spec, *av);
 	}
 }
diff --git a/bin/varnishtest/vtc_http.c b/bin/varnishtest/vtc_http.c
index d04b666..46f6d68 100644
--- a/bin/varnishtest/vtc_http.c
+++ b/bin/varnishtest/vtc_http.c
@@ -140,22 +140,22 @@ static const struct cmds http_cmds[];
 #define ONLY_CLIENT(hp, av)						\
 	do {								\
 		if (hp->h2)						\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible before H/2 upgrade",	\
 					av[0]);				\
 		if (hp->sfd != NULL)					\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible in client", av[0]);	\
 	} while (0)
 
 #define ONLY_SERVER(hp, av)						\
 	do {								\
 		if (hp->h2)						\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible before H/2 upgrade",	\
 					av[0]);				\
 		if (hp->sfd == NULL)					\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible in server", av[0]);	\
 	} while (0)
 
@@ -373,7 +373,7 @@ cmd_http_expect(CMD_ARGS)
 	if (!strcmp(cmp, "~") || !strcmp(cmp, "!~")) {
 		vre = VRE_compile(crhs, 0, &error, &erroroffset);
 		if (vre == NULL)
-			vtc_log(hp->vl, 0, "REGEXP error: %s (@%d) (%s)",
+			vtc_fatal(hp->vl, "REGEXP error: %s (@%d) (%s)",
 			    error, erroroffset, crhs);
 		i = VRE_exec(vre, clhs, strlen(clhs), 0, 0, NULL, 0, 0);
 		retval = (i >= 0 && *cmp == '~') || (i < 0 && *cmp == '!');
@@ -396,7 +396,7 @@ cmd_http_expect(CMD_ARGS)
 	}
 
 	if (retval == -1)
-		vtc_log(hp->vl, 0,
+		vtc_fatal(hp->vl,
 		    "EXPECT %s (%s) %s %s (%s) test not implemented",
 		    av[0], clhs, av[1], av[2], crhs);
 	else
@@ -419,7 +419,7 @@ cmd_http_expect_pattern(CMD_ARGS)
 	AZ(av[0]);
 	for (p = hp->body; *p != '\0'; p++) {
 		if (*p != t)
-			vtc_log(hp->vl, 0,
+			vtc_fatal(hp->vl,
 			    "EXPECT PATTERN FAIL @%zd should 0x%02x is 0x%02x",
 			    p - hp->body, t, *p);
 		t += 1;
@@ -694,12 +694,12 @@ cmd_http_rxresp(CMD_ARGS)
 		if (!strcmp(*av, "-no_obj"))
 			has_obj = 0;
 		else
-			vtc_log(hp->vl, 0,
+			vtc_fatal(hp->vl,
 			    "Unknown http rxresp spec: %s\n", *av);
 	http_rxhdr(hp);
 	http_splitheader(hp, 0);
 	if (http_count_header(hp->resp, "Content-Length") > 1)
-		vtc_log(hp->vl, 0,
+		vtc_fatal(hp->vl,
 		    "Multiple Content-Length headers.\n");
 	if (!has_obj)
 		return;
@@ -728,11 +728,11 @@ cmd_http_rxresphdrs(CMD_ARGS)
 	av++;
 
 	for(; *av != NULL; av++)
-		vtc_log(hp->vl, 0, "Unknown http rxresp spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http rxresp spec: %s\n", *av);
 	http_rxhdr(hp);
 	http_splitheader(hp, 0);
 	if (http_count_header(hp->resp, "Content-Length") > 1)
-		vtc_log(hp->vl, 0,
+		vtc_fatal(hp->vl,
 		    "Multiple Content-Length headers.\n");
 }
 
@@ -1026,7 +1026,7 @@ cmd_http_txresp(CMD_ARGS)
 
 	av = http_tx_parse_args(av, vl, hp, body);
 	if (*av != NULL)
-		vtc_log(hp->vl, 0, "Unknown http txresp spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http txresp spec: %s\n", *av);
 
 	http_write(hp, 4, "txresp");
 }
@@ -1043,16 +1043,16 @@ cmd_http_upgrade(CMD_ARGS)
 
 	h = http_find_header(hp->req, "Upgrade");
 	if (!h || strcmp(h, "h2c"))
-		vtc_log(vl, 0, "Req misses \"Upgrade: h2c\" header");
+		vtc_fatal(vl, "Req misses \"Upgrade: h2c\" header");
 
 	h = http_find_header(hp->req, "Connection");
 	if (!h || strcmp(h, "Upgrade, HTTP2-Settings"))
-		vtc_log(vl, 0, "Req misses \"Connection: "
+		vtc_fatal(vl, "Req misses \"Connection: "
 			"Upgrade, HTTP2-Settings\" header");
 
 	h = http_find_header(hp->req, "HTTP2-Settings");
 	if (!h)
-		vtc_log(vl, 0, "Req misses \"HTTP2-Settings\" header");
+		vtc_fatal(vl, "Req misses \"HTTP2-Settings\" header");
 
 
 	parse_string("txresp -status 101 "
@@ -1092,11 +1092,11 @@ cmd_http_rxreq(CMD_ARGS)
 	av++;
 
 	for(; *av != NULL; av++)
-		vtc_log(vl, 0, "Unknown http rxreq spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown http rxreq spec: %s\n", *av);
 	http_rxhdr(hp);
 	http_splitheader(hp, 1);
 	if (http_count_header(hp->req, "Content-Length") > 1)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "Multiple Content-Length headers.\n");
 	http_swallow_body(hp, hp->req, 0);
 	vtc_log(vl, 4, "bodylen = %s", hp->bodylen);
@@ -1120,11 +1120,11 @@ cmd_http_rxreqhdrs(CMD_ARGS)
 	av++;
 
 	for(; *av != NULL; av++)
-		vtc_log(hp->vl, 0, "Unknown http rxreq spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http rxreq spec: %s\n", *av);
 	http_rxhdr(hp);
 	http_splitheader(hp, 1);
 	if (http_count_header(hp->req, "Content-Length") > 1)
-		vtc_log(hp->vl, 0,
+		vtc_fatal(hp->vl,
 		    "Multiple Content-Length headers.\n");
 }
 
@@ -1147,7 +1147,7 @@ cmd_http_rxreqbody(CMD_ARGS)
 	av++;
 
 	for(; *av != NULL; av++)
-		vtc_log(hp->vl, 0, "Unknown http rxreq spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http rxreq spec: %s\n", *av);
 	http_swallow_body(hp, hp->req, 0);
 	vtc_log(hp->vl, 4, "bodylen = %s", hp->bodylen);
 }
@@ -1171,7 +1171,7 @@ cmd_http_rxrespbody(CMD_ARGS)
 	av++;
 
 	for(; *av != NULL; av++)
-		vtc_log(hp->vl, 0, "Unknown http rxrespbody spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http rxrespbody spec: %s\n", *av);
 	http_swallow_body(hp, hp->resp, 0);
 	vtc_log(hp->vl, 4, "bodylen = %s", hp->bodylen);
 }
@@ -1249,7 +1249,7 @@ cmd_http_txreq(CMD_ARGS)
 
 	av = http_tx_parse_args(av, vl, hp, NULL);
 	if (*av != NULL)
-		vtc_log(hp->vl, 0, "Unknown http txreq spec: %s\n", *av);
+		vtc_fatal(hp->vl, "Unknown http txreq spec: %s\n", *av);
 	http_write(hp, 4, "txreq");
 
 	if (up) {
@@ -1411,7 +1411,7 @@ cmd_http_sendhex(CMD_ARGS)
 		q += 2;
 		buf[2] = '\0';
 		if (!vct_ishex(buf[0]) || !vct_ishex(buf[1]))
-			vtc_log(hp->vl, 0, "Illegal Hex char \"%c%c\"",
+			vtc_fatal(hp->vl, "Illegal Hex char \"%c%c\"",
 			    buf[0], buf[1]);
 		p[i] = (uint8_t)strtoul(buf, NULL, 16);
 	}
@@ -1506,7 +1506,7 @@ cmd_http_timeout(CMD_ARGS)
 	AZ(av[2]);
 	d = VNUM(av[1]);
 	if (isnan(d))
-		vtc_log(vl, 0, "timeout is not a number (%s)", av[1]);
+		vtc_fatal(vl, "timeout is not a number (%s)", av[1]);
 	hp->timeout = (int)(d * 1000.0);
 }
 
@@ -1649,7 +1649,7 @@ cmd_http_fatal(CMD_ARGS)
 	else if (!strcmp(av[0], "non_fatal"))
 		hp->fatal = -1;
 	else {
-		vtc_log(vl, 0, "XXX: fatal %s", cmd->name);
+		vtc_fatal(vl, "XXX: fatal %s", cmd->name);
 	}
 }
 
@@ -1715,9 +1715,9 @@ cmd_http_rxpri(CMD_ARGS)
 
 	hp->prxbuf = 0;
 	if (!http_rxchar(hp, sizeof(PREFACE), 0))
-		vtc_log(vl, 0, "Couldn't retrieve connection preface");
+		vtc_fatal(vl, "Couldn't retrieve connection preface");
 	if (memcmp(hp->rxbuf, PREFACE, sizeof(PREFACE)))
-		vtc_log(vl, 0, "Received invalid preface\n");
+		vtc_fatal(vl, "Received invalid preface\n");
 	start_h2(hp);
 	AN(hp->h2);
 }
@@ -1738,7 +1738,7 @@ cmd_http_settings(CMD_ARGS)
 	(void)cmd;
 
 	if (!hp->h2)
-		vtc_log(hp->vl, 0, "Only possible in H/2 mode");
+		vtc_fatal(hp->vl, "Only possible in H/2 mode");
 
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 
@@ -1746,12 +1746,12 @@ cmd_http_settings(CMD_ARGS)
 		if (!strcmp(*av, "-dectbl")) {
 			n = strtoul(av[1], &p, 0);
 			if (*p != '\0')
-				vtc_log(hp->vl, 0, "-dectbl takes an integer as"
+				vtc_fatal(hp->vl, "-dectbl takes an integer as"
 						" argument (found %s)", av[1]);
 			HPK_ResizeTbl(hp->decctx, n);
 			av++;
 		} else
-			vtc_log(vl, 0, "Unknown settings spec: %s\n", *av);
+			vtc_fatal(vl, "Unknown settings spec: %s\n", *av);
 	}
 }
 
@@ -1798,7 +1798,7 @@ cmd_http_write_body(CMD_ARGS)
 	AZ(av[2]);
 	AZ(strcmp(av[0], "write_body"));
 	if (VFIL_writefile(NULL, av[1], hp->body, hp->bodyl) != 0)
-		vtc_log(hp->vl, 0, "failed to write body: %s (%d)",
+		vtc_fatal(hp->vl, "failed to write body: %s (%d)",
 		    strerror(errno), errno);
 }
 
diff --git a/bin/varnishtest/vtc_http2.c b/bin/varnishtest/vtc_http2.c
index 6b58b73..449208e 100644
--- a/bin/varnishtest/vtc_http2.c
+++ b/bin/varnishtest/vtc_http2.c
@@ -131,14 +131,14 @@ clean_headers(struct hpk_hdr *h)
 #define ONLY_CLIENT(hp, av)						\
 	do {								\
 		if (hp->sfd != NULL)					\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible in client", av[0]);	\
 	} while (0)
 
 #define ONLY_SERVER(hp, av)						\
 	do {								\
 		if (hp->sfd == NULL)					\
-			vtc_log(hp->vl, 0,				\
+			vtc_fatal(hp->vl,				\
 			    "\"%s\" only possible in server", av[0]);	\
 	} while (0)
 
@@ -537,7 +537,7 @@ parse_prio(struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 5)
-		vtc_log(hp->vl, 0, "Size should be 5, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be 5, but isn't (%d)", f->size);
 
 	buf = f->data;
 	AN(buf);
@@ -570,7 +570,7 @@ parse_rst(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 4)
-		vtc_log(hp->vl, 0, "Size should be 4, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be 4, but isn't (%d)", f->size);
 
 	err = vbe32dec(f->data);
 	f->md.rst_err = err;
@@ -596,7 +596,7 @@ parse_settings(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size % 6)
-		vtc_log(hp->vl, 0, "Size should be a multiple of 6, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be a multiple of 6, but isn't (%d)", f->size);
 
 	for (i = 0; i <= SETTINGS_MAX; i++)
 		f->md.settings[i] = NAN;
@@ -630,7 +630,7 @@ parse_ping(const struct stream *s, struct frame *f)
 	CHECK_OBJ_NOTNULL(s, STREAM_MAGIC);
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 	if (f->size != 8)
-		vtc_log(hp->vl, 0, "Size should be 8, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be 8, but isn't (%d)", f->size);
 	f->md.ping.ack = f->flags & ACK;
 	memcpy(f->md.ping.data, f->data, 8);
 	f->md.ping.data[8] = '\0';
@@ -650,9 +650,9 @@ parse_goaway(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size < 8)
-		vtc_log(hp->vl, 0, "Size should be at least 8, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be at least 8, but isn't (%d)", f->size);
 	if (f->data[0] & (1<<7))
-		vtc_log(hp->vl, 0, "First bit of data is reserved and should be 0");
+		vtc_fatal(hp->vl, "First bit of data is reserved and should be 0");
 
 	stid = vbe32dec(f->data);
 	err = vbe32dec(f->data + 4);
@@ -688,7 +688,7 @@ parse_winup(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 4)
-		vtc_log(hp->vl, 0, "Size should be 4, but isn't (%d)", f->size);
+		vtc_fatal(hp->vl, "Size should be 4, but isn't (%d)", f->size);
 	if (f->data[0] & (1<<7))
 		vtc_log(hp->vl, s->hp->fatal, "First bit of data is reserved and should be 0");
 
@@ -764,7 +764,7 @@ receive_frame(void *priv)
 
 		if (expect_cont && (f->type != TYPE_CONTINUATION ||
 					expect_cont != s->id))
-			vtc_log(hp->vl, 0, "Expected CONTINUATION frame for"
+			vtc_fatal(hp->vl, "Expected CONTINUATION frame for"
 					" stream %u", expect_cont);
 
 		/* parse the frame according to it type, and fill the metada */
@@ -834,7 +834,7 @@ receive_frame(void *priv)
 	do { \
 	n = strtoul(s, &p, 0); \
 	if (*p != '\0') { \
-		vtc_log(v, 0, "%s takes an integer as argument" \
+		vtc_fatal(v, "%s takes an integer as argument" \
 			"(found %s)", c, s); \
 		WRONG("Couldn't convert to integer");\
 	} \
@@ -846,13 +846,13 @@ do {									\
 	AN(*sp);							\
 	STRTOU32(n, *sp, p, v, c);					\
 	if (l && n >= (1U << l))					\
-		vtc_log(v, 0,						\
+		vtc_fatal(v,						\
 		    c " must be a %d-bits integer (found %s)", l, *sp);	\
 } while (0)
 
 #define CHECK_LAST_FRAME(TYPE) \
 	if (!f || f->type != TYPE_ ## TYPE) { \
-		vtc_log(s->hp->vl, 0, "Last frame was not of type " #TYPE); \
+		vtc_fatal(s->hp->vl, "Last frame was not of type " #TYPE); \
 	}
 
 #define RETURN_SETTINGS(idx) \
@@ -1060,7 +1060,7 @@ cmd_var_resolve(const struct stream *s, const char *spec, char *buf)
 	else if (!strncmp(spec, "frame.", 6)) {
 		spec += 6;
 		if (!f)
-			vtc_log(s->hp->vl, 0, "No frame received yet.");
+			vtc_fatal(s->hp->vl, "No frame received yet.");
 		if (!strcmp(spec, "data"))   { return (f->data); }
 		else if (!strcmp(spec, "type"))   { RETURN_BUFFED(f->type); }
 		else if (!strcmp(spec, "size"))	  { RETURN_BUFFED(f->size); }
@@ -1069,7 +1069,7 @@ cmd_var_resolve(const struct stream *s, const char *spec, char *buf)
 			if (f->type != TYPE_DATA &&
 					f->type != TYPE_HEADERS &&
 					f->type != TYPE_PUSH_PROMISE)
-				vtc_log(s->hp->vl, 0,
+				vtc_fatal(s->hp->vl,
 						"Last frame was not of type "
 						"DATA, HEADERS or PUSH");
 			RETURN_BUFFED(f->md.padded);
@@ -1252,7 +1252,7 @@ cmd_sendhex(CMD_ARGS)
 		q += 2;
 		tmp[2] = '\0';
 		if (!vct_ishex(tmp[0]) || !vct_ishex(tmp[1]))
-			vtc_log(vl, 0, "Illegal Hex char \"%c%c\"",
+			vtc_fatal(vl, "Illegal Hex char \"%c%c\"",
 					tmp[0], tmp[1]);
 		buf[i] = (uint8_t)strtoul(tmp, NULL, 16);
 	}
@@ -1285,7 +1285,7 @@ cmd_sendhex(CMD_ARGS)
 	     if (AV_IS("plain")) { hdr.field.huff = 0; }		       \
 	else if (AV_IS("huf"))   { hdr.field.huff = 1; }		       \
 	else								       \
-		vtc_log(vl, 0, str " arg can be huf or plain (got: %s)", *av); \
+		vtc_fatal(vl, str " arg can be huf or plain (got: %s)", *av); \
 	av++;								       \
 	AN(*av);							       \
 	hdr.field.ptr = *av;						       \
@@ -1484,7 +1484,7 @@ cmd_tx11obj(CMD_ARGS)
 			else if (AV_IS("not"))   { hdr.t = hpk_not;   }
 			else if (AV_IS("never")) { hdr.t = hpk_never; }
 			else
-				vtc_log(vl, 0, "first -litidxHdr arg can be "
+				vtc_fatal(vl, "first -litidxHdr arg can be "
 						"inc, not, never (got: %s)",
 						*av);
 
@@ -1502,7 +1502,7 @@ cmd_tx11obj(CMD_ARGS)
 			else if (AV_IS("not"))   { hdr.t = hpk_not;   }
 			else if (AV_IS("never")) { hdr.t = hpk_never; }
 			else
-				vtc_log(vl, 0, "first -litHdr arg can be inc, "
+				vtc_fatal(vl, "first -litHdr arg can be inc, "
 						"not, never (got: %s)", *av);
 
 			STR_ENC(av, key,   "second -litHdr");
@@ -1561,7 +1561,7 @@ cmd_tx11obj(CMD_ARGS)
 #undef CMD_IS
 #undef AV_IS
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown %s spec: %s\n", cmd_str, *av);
+		vtc_fatal(vl, "Unknown %s spec: %s\n", cmd_str, *av);
 
 	memset(&hdr, 0, sizeof(hdr));
 	hdr.t = hpk_not;
@@ -1589,7 +1589,7 @@ cmd_tx11obj(CMD_ARGS)
 	}
 	if (pad) {
 		if (strlen(pad) >= 128)
-			vtc_log(vl, 0, "Padding is limited to 128 bytes");
+			vtc_fatal(vl, "Padding is limited to 128 bytes");
 		f.flags |= PADDED;
 		assert(f.size + strlen(pad) < BUF_SIZE);
 		memmove(buf + 1, buf, f.size);
@@ -1675,7 +1675,7 @@ cmd_txdata(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txdata spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txdata spec: %s\n", *av);
 
 	if (!body)
 		body = strdup("");
@@ -1683,7 +1683,7 @@ cmd_txdata(CMD_ARGS)
 	if (pad) {
 		f.flags |= PADDED;
 		if (strlen(pad) >= 128)
-			vtc_log(vl, 0, "Padding is limited to 128 bytes");
+			vtc_fatal(vl, "Padding is limited to 128 bytes");
 		data = malloc( 1 + strlen(body) + strlen(pad));
 		AN(data);
 		*((uint8_t *)data) = strlen(pad);
@@ -1741,7 +1741,7 @@ cmd_txrst(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txrst spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txrst spec: %s\n", *av);
 
 	err = htonl(err);
 	f.data = (void *)&err;
@@ -1791,7 +1791,7 @@ cmd_txprio(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txprio spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txprio spec: %s\n", *av);
 	s->weight = weight & 0xff;
 	s->dependency = stid;
 
@@ -1870,7 +1870,7 @@ cmd_txsettings(CMD_ARGS)
 			else if (!strcmp(*av, "true"))
 				vbe32enc(cursor, 1);
 			else
-				vtc_log(vl, 0, "Push parameter is either "
+				vtc_fatal(vl, "Push parameter is either "
 						"\"true\" or \"false\", not %s",
 						*av);
 			cursor += sizeof(uint32_t);
@@ -1901,7 +1901,7 @@ cmd_txsettings(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txsettings spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txsettings spec: %s\n", *av);
 
 	write_frame(hp, &f, 0);
 	AZ(pthread_mutex_unlock(&hp->mtx));
@@ -1933,9 +1933,9 @@ cmd_txping(CMD_ARGS)
 		if (!strcmp(*av, "-data")) {
 			av++;
 			if (f.data)
-				vtc_log(vl, 0, "this frame already has data");
+				vtc_fatal(vl, "this frame already has data");
 			if (strlen(*av) != 8)
-				vtc_log(vl, 0, "data must be a 8-char string, found  (%s)", *av);
+				vtc_fatal(vl, "data must be a 8-char string, found  (%s)", *av);
 			f.data = *av;
 		} else if (!strcmp(*av, "-ack")) {
 			f.flags |= 1;
@@ -1943,7 +1943,7 @@ cmd_txping(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txping spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txping spec: %s\n", *av);
 	if (!f.data)
 		f.data = buf;
 	write_frame(s->hp, &f, 1);
@@ -2000,7 +2000,7 @@ cmd_txgoaway(CMD_ARGS)
 		} else if (!strcmp(*av, "-debug")) {
 			++av;
 			if (f.data)
-				vtc_log(vl, 0, "this frame already has debug data");
+				vtc_fatal(vl, "this frame already has debug data");
 			f.size = 8 + strlen(*av);
 			f.data = malloc(f.size);
 			memcpy(f.data + 8, *av, f.size - 8);
@@ -2008,7 +2008,7 @@ cmd_txgoaway(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txgoaway spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txgoaway spec: %s\n", *av);
 
 	if (!f.data)
 		f.data = malloc(2);
@@ -2054,7 +2054,7 @@ cmd_txwinup(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown txwinup spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown txwinup spec: %s\n", *av);
 
 	AZ(pthread_mutex_lock(&hp->mtx));
 	if (s->id == 0)
@@ -2096,7 +2096,7 @@ rxstuff(struct stream *s)
 #define CHKFRAME(rt, wt, rcv, func) \
 	do { \
 	if (rt != wt) \
-		vtc_log(vl, 0, "Frame #%d for %s was of type %s (%d) " \
+		vtc_fatal(vl, "Frame #%d for %s was of type %s (%d) " \
 				"instead of %s (%d)", \
 				rcv, func, \
 				rt < TYPE_MAX ? h2_types[rt] : "?", rt, \
@@ -2139,7 +2139,7 @@ cmd_rxhdrs(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown rxhdrs spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown rxhdrs spec: %s\n", *av);
 
 	while (rcv++ < times || (loop && !(f->flags & END_HEADERS))) {
 		f = rxstuff(s);
@@ -2174,7 +2174,7 @@ cmd_rxcont(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown rxcont spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown rxcont spec: %s\n", *av);
 
 	while (rcv++ < times || (loop && !(f->flags & END_HEADERS))) {
 		f = rxstuff(s);
@@ -2222,7 +2222,7 @@ cmd_rxdata(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown rxdata spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown rxdata spec: %s\n", *av);
 
 	while (rcv++ < times || (loop && !(f->flags & END_STREAM))) {
 		f = rxstuff(s);
@@ -2321,7 +2321,7 @@ cmd_rxpush(CMD_ARGS)
 			break;
 	}
 	if (*av != NULL)
-		vtc_log(vl, 0, "Unknown rxpush spec: %s\n", *av);
+		vtc_fatal(vl, "Unknown rxpush spec: %s\n", *av);
 
 	while (rcv++ < times || (loop && !(f->flags & END_HEADERS))) {
 		f = rxstuff(s);
@@ -2343,7 +2343,7 @@ cmd_rxpush(CMD_ARGS)
 		if ((s->frame = rxstuff(s))) \
 				return; \
 		if (s->frame->type != TYPE_ ## upctype) \
-			vtc_log(vl, 0, "Received frame of type %d " \
+			vtc_fatal(vl, "Received frame of type %d " \
 					"is invalid for %s", \
 					s->frame->type, "rx ## lctype"); \
 	}
@@ -2436,7 +2436,7 @@ cmd_expect(CMD_ARGS)
 	if (!strcmp(cmp, "~") || !strcmp(cmp, "!~")) {
 		vre = VRE_compile(crhs, 0, &error, &erroroffset);
 		if (vre == NULL)
-			vtc_log(vl, 0, "REGEXP error: %s (@%d) (%s)",
+			vtc_fatal(vl, "REGEXP error: %s (@%d) (%s)",
 			    error, erroroffset, crhs);
 		i = VRE_exec(vre, clhs, strlen(clhs), 0, 0, NULL, 0, 0);
 		retval = (i >= 0 && *cmp == '~') || (i < 0 && *cmp == '!');
@@ -2459,7 +2459,7 @@ cmd_expect(CMD_ARGS)
 	}
 
 	if (retval == -1)
-		vtc_log(vl, 0,
+		vtc_fatal(vl,
 		    "EXPECT %s (%s) %s %s (%s) test not implemented",
 		    av[0], clhs, av[1], av[2], crhs);
 	else
@@ -2486,7 +2486,7 @@ cmd_write_body(CMD_ARGS)
 	AZ(av[2]);
 	AZ(strcmp(av[0], "write_body"));
 	if (VFIL_writefile(NULL, av[1], s->body, s->bodylen) != 0)
-		vtc_log(s->hp->vl, 0, "failed to write body: %s (%d)",
+		vtc_fatal(s->hp->vl, "failed to write body: %s (%d)",
 		    strerror(errno), errno);
 }
 
@@ -2574,7 +2574,7 @@ stream_new(const char *name, struct http *h)
 
 	STRTOU32(s->id, name, p, h->vl, "stream");
 	if (s->id & (1U << 31))
-		vtc_log(h->vl, 0, "Stream id must be a 31-bits integer "
+		vtc_fatal(h->vl, "Stream id must be a 31-bits integer "
 				"(found %s)", name);
 
 	CHECK_OBJ_NOTNULL(h, HTTP_MAGIC);
@@ -2626,7 +2626,7 @@ stream_wait(struct stream *s)
 	vtc_log(s->hp->vl, 2, "Waiting for stream %u", s->id);
 	AZ(pthread_join(s->tp, &res));
 	if (res != NULL)
-		vtc_log(s->hp->vl, 0, "Stream %u returned \"%s\"", s->id,
+		vtc_fatal(s->hp->vl, "Stream %u returned \"%s\"", s->id,
 				(char *)res);
 
 	VTAILQ_FOREACH_SAFE(f, &s->fq, list, f2)
@@ -2740,7 +2740,7 @@ cmd_stream(CMD_ARGS)
 			continue;
 		}
 		if (**av == '-')
-			vtc_log(vl, 0, "Unknown client argument: %s", *av);
+			vtc_fatal(vl, "Unknown client argument: %s", *av);
 		REPLACE(s->spec, *av);
 	}
 }
@@ -2766,7 +2766,7 @@ b64_settings(const struct http *hp, const char *s)
 			else if (*s == '_') {
 				v |= (uint64_t)63 << shift;
 			} else
-				vtc_log(hp->vl, 0, "Bad \"HTTP2-Settings\" "
+				vtc_fatal(hp->vl, "Bad \"HTTP2-Settings\" "
 						"header");
 			s++;
 		}
diff --git a/bin/varnishtest/vtc_log.c b/bin/varnishtest/vtc_log.c
index b111d28..b415302 100644
--- a/bin/varnishtest/vtc_log.c
+++ b/bin/varnishtest/vtc_log.c
@@ -48,6 +48,7 @@ struct vtclog {
 	struct vsb	*vsb;
 	pthread_mutex_t	mtx;
 	int		act;
+	double		tx;
 };
 
 static pthread_key_t log_key;
@@ -55,6 +56,24 @@ static double t0;
 
 /**********************************************************************/
 
+#define GET_VL(vl)					\
+	do {						\
+		CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);	\
+		vl->tx = VTIM_mono() - t0;		\
+		AZ(pthread_mutex_lock(&vl->mtx));	\
+		vl->act = 1;				\
+		VSB_clear(vl->vsb);			\
+	} while(0)
+
+#define REL_VL(vl)					\
+	do {						\
+		AZ(VSB_finish(vl->vsb));		\
+		vtc_log_emit(vl);			\
+		VSB_clear(vl->vsb);			\
+		vl->act = 0;				\
+		AZ(pthread_mutex_unlock(&vl->mtx));	\
+	} while(0)
+
 
 struct vtclog *
 vtc_logopen(const char *id)
@@ -93,13 +112,36 @@ static const char * const lead[] = {
 #define NLEAD (sizeof(lead)/sizeof(lead[0]))
 
 static void
-vtc_log_emit(const struct vtclog *vl, int lvl)
+vtc_leadinv(const struct vtclog *vl, int lvl, const char *fmt, va_list ap)
+{
+
+	assert(lvl < (int)NLEAD);
+	assert(lvl >= 0);
+	VSB_clear(vl->vsb);
+	VSB_printf(vl->vsb, "%s %-4s %4.1f ",
+	    lead[lvl < 0 ? 1: lvl], vl->id, vl->tx);
+	if (fmt != NULL)
+		(void)VSB_vprintf(vl->vsb, fmt, ap);
+}
+
+static void
+vtc_leadin(const struct vtclog *vl, int lvl, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	vtc_leadinv(vl, lvl, fmt, ap);
+	va_end(ap);
+}
+
+static void
+vtc_log_emit(const struct vtclog *vl)
 {
 	int l;
 
-	if (lvl < 0)
-		lvl = 0;
 	l = VSB_len(vl->vsb);
+	if (l == 0)
+		return;
 	AZ(pthread_mutex_lock(&vtclog_mtx));
 	assert(vtclog_left > l);
 	memcpy(vtclog_buf,VSB_data(vl->vsb), l);
@@ -109,32 +151,37 @@ vtc_log_emit(const struct vtclog *vl, int lvl)
 	AZ(pthread_mutex_unlock(&vtclog_mtx));
 }
 
-//lint -e{818}
 void
-vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
+vtc_fatal(struct vtclog *vl, const char *fmt, ...)
 {
-	double tx;
 
-	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
-	tx = VTIM_mono() - t0;
-	AZ(pthread_mutex_lock(&vl->mtx));
-	vl->act = 1;
-	assert(lvl < (int)NLEAD);
-	VSB_clear(vl->vsb);
-	VSB_printf(vl->vsb, "%s %-4s %4.1f ",
-	    lead[lvl < 0 ? 1: lvl], vl->id, tx);
+	GET_VL(vl);
 	va_list ap;
 	va_start(ap, fmt);
-	(void)VSB_vprintf(vl->vsb, fmt, ap);
-	va_end(ap);
+	vtc_leadinv(vl, 0, fmt, ap);
 	VSB_putc(vl->vsb, '\n');
-	AZ(VSB_finish(vl->vsb));
+	va_end(ap);
+	REL_VL(vl);
 
-	vtc_log_emit(vl, lvl);
+	vtc_error = 2;
+	if (pthread_self() != vtc_thread)
+		pthread_exit(NULL);
+	while(1) continue;
+}
+void
+vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
+{
+
+	GET_VL(vl);
+	va_list ap;
+	va_start(ap, fmt);
+	if (lvl >= 0) {
+		vtc_leadinv(vl, lvl, fmt, ap);
+		VSB_putc(vl->vsb, '\n');
+	}
+	va_end(ap);
+	REL_VL(vl);
 
-	VSB_clear(vl->vsb);
-	vl->act = 0;
-	AZ(pthread_mutex_unlock(&vl->mtx));
 	if (lvl > 0)
 		return;
 	if (lvl == 0)
@@ -147,26 +194,16 @@ vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
  * Dump a string
  */
 
-//lint -e{818}
 void
 vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
 {
 	int nl = 1, olen;
 	unsigned l;
-	double tx;
 
-	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
-	tx = VTIM_mono() - t0;
-	assert(lvl >= 0);
-	assert(lvl < NLEAD);
-	AZ(pthread_mutex_lock(&vl->mtx));
-	vl->act = 1;
-	VSB_clear(vl->vsb);
-	if (pfx == NULL)
-		pfx = "";
+	AN(pfx);
+	GET_VL(vl);
 	if (str == NULL)
-		VSB_printf(vl->vsb, "%s %-4s %4.1f %s(null)\n",
-		    lead[lvl], vl->id, tx, pfx);
+		vtc_leadin(vl, lvl, "%s(null)\n", pfx);
 	else {
 		olen = len;
 		if (len < 0)
@@ -177,8 +214,7 @@ vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
 				break;
 			}
 			if (nl) {
-				VSB_printf(vl->vsb, "%s %-4s %4.1f %s| ",
-				    lead[lvl], vl->id, tx, pfx);
+				vtc_leadin(vl, lvl, "%s| ", pfx);
 				nl = 0;
 			}
 			if (*str == '\r')
@@ -196,13 +232,7 @@ vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
 	}
 	if (!nl)
 		VSB_printf(vl->vsb, "\n");
-	AZ(VSB_finish(vl->vsb));
-
-	vtc_log_emit(vl, lvl);
-
-	VSB_clear(vl->vsb);
-	vl->act = 0;
-	AZ(pthread_mutex_unlock(&vl->mtx));
+	REL_VL(vl);
 	if (lvl == 0) {
 		vtc_error = 2;
 		if (pthread_self() != vtc_thread)
@@ -214,28 +244,17 @@ vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
  * Hexdump
  */
 
-//lint -e{818}
 void
 vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
     const unsigned char *str, int len)
 {
 	int nl = 1;
 	unsigned l;
-	double tx;
 
-	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
-	tx = VTIM_mono() - t0;
-	assert(len >= 0);
-	assert(lvl >= 0);
-	assert(lvl < NLEAD);
-	AZ(pthread_mutex_lock(&vl->mtx));
-	vl->act = 1;
-	VSB_clear(vl->vsb);
-	if (pfx == NULL)
-		pfx = "";
+	AN(pfx);
+	GET_VL(vl);
 	if (str == NULL)
-		VSB_printf(vl->vsb, "%s %-4s %4.1f %s| (null)",
-		    lead[lvl], vl->id, tx, pfx);
+		vtc_leadin(vl, lvl, "%s(null)\n", pfx);
 	else {
 		for (l = 0; l < len; l++, str++) {
 			if (l > 512) {
@@ -243,8 +262,7 @@ vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
 				break;
 			}
 			if (nl) {
-				VSB_printf(vl->vsb, "%s %-4s %4.1f %s| ",
-				    lead[lvl], vl->id, tx, pfx);
+				vtc_leadin(vl, lvl, "%s| ", pfx);
 				nl = 0;
 			}
 			VSB_printf(vl->vsb, " %02x", *str);
@@ -256,13 +274,7 @@ vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
 	}
 	if (!nl)
 		VSB_printf(vl->vsb, "\n");
-	AZ(VSB_finish(vl->vsb));
-
-	vtc_log_emit(vl, lvl);
-
-	VSB_clear(vl->vsb);
-	vl->act = 0;
-	AZ(pthread_mutex_unlock(&vl->mtx));
+	REL_VL(vl);
 	if (lvl == 0) {
 		vtc_error = 2;
 		if (pthread_self() != vtc_thread)
@@ -286,7 +298,7 @@ vtc_log_VAS_Fail(const char *func, const char *file, int line,
 		    "  Condition(%s) not true.\n",
 		    func, file, line, cond);
 	} else {
-		vtc_log(vl, 0, "Assert error in %s(), %s line %d:"
+		vtc_fatal(vl, "Assert error in %s(), %s line %d:"
 		    "  Condition(%s) not true.\n", func, file, line, cond);
 	}
 	abort();
diff --git a/bin/varnishtest/vtc_logexp.c b/bin/varnishtest/vtc_logexp.c
index eb2843a..af7e6a1 100644
--- a/bin/varnishtest/vtc_logexp.c
+++ b/bin/varnishtest/vtc_logexp.c
@@ -343,9 +343,9 @@ logexp_thread(void *priv)
 	while (le->test) {
 		i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
 		if (i == 2)
-			vtc_log(le->vl, 0, "bad| expectation failed");
+			vtc_fatal(le->vl, "bad| expectation failed");
 		else if (i < 0)
-			vtc_log(le->vl, 0, "bad| dispatch failed (%d)", i);
+			vtc_fatal(le->vl, "bad| dispatch failed (%d)", i);
 		else if (i == 0 && le->test)
 			VTIM_sleep(0.01);
 	}
@@ -376,30 +376,30 @@ logexp_start(struct logexp *le)
 	AZ(le->vslq);
 
 	if (le->n_arg == NULL) {
-		vtc_log(le->vl, 0, "-v argument not given");
+		vtc_fatal(le->vl, "-v argument not given");
 		return;
 	}
 	if (VSM_n_Arg(le->vsm, VSB_data(le->n_arg)) <= 0) {
-		vtc_log(le->vl, 0, "-v argument error: %s",
+		vtc_fatal(le->vl, "-v argument error: %s",
 		    VSM_Error(le->vsm));
 		return;
 	}
 	if (VSM_Open(le->vsm)) {
-		vtc_log(le->vl, 0, "VSM_Open: %s", VSM_Error(le->vsm));
+		vtc_fatal(le->vl, "VSM_Open: %s", VSM_Error(le->vsm));
 		return;
 	}
 	AN(le->vsl);
 	c = VSL_CursorVSM(le->vsl, le->vsm,
 	    (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
 	if (c == NULL) {
-		vtc_log(le->vl, 0, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
+		vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
 		logexp_close(le);
 		return;
 	}
 	le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
 	if (le->vslq == NULL) {
 		VSL_DeleteCursor(c);
-		vtc_log(le->vl, 0, "VSLQ_New: %s", VSL_Error(le->vsl));
+		vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
 		AZ(le->vslq);
 		logexp_close(le);
 		return;
@@ -423,7 +423,7 @@ logexp_wait(struct logexp *le)
 	AZ(pthread_join(le->tp, &res));
 	logexp_close(le);
 	if (res != NULL && !vtc_stop)
-		vtc_log(le->vl, 0, "logexp returned \"%p\"", (char *)res);
+		vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
 	le->run = 0;
 }
 
@@ -443,7 +443,7 @@ cmd_logexp_expect(CMD_ARGS)
 	(void)cmd;
 	CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
 	if (av[1] == NULL || av[2] == NULL || av[3] == NULL) {
-		vtc_log(vl, 0, "Syntax error");
+		vtc_fatal(vl, "Syntax error");
 		return;
 	}
 
@@ -452,7 +452,7 @@ cmd_logexp_expect(CMD_ARGS)
 	else {
 		skip_max = (int)strtol(av[1], &end, 10);
 		if (*end != '\0' || skip_max < 0) {
-			vtc_log(vl, 0, "Not a positive integer: '%s'", av[1]);
+			vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
 			return;
 		}
 	}
@@ -463,7 +463,7 @@ cmd_logexp_expect(CMD_ARGS)
 	else {
 		vxid = (int)strtol(av[2], &end, 10);
 		if (*end != '\0' || vxid < 0) {
-			vtc_log(vl, 0, "Not a positive integer: '%s'", av[2]);
+			vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
 			return;
 		}
 	}
@@ -474,7 +474,7 @@ cmd_logexp_expect(CMD_ARGS)
 	else {
 		tag = VSL_Name2Tag(av[3], strlen(av[3]));
 		if (tag < 0) {
-			vtc_log(vl, 0, "Unknown tag name: '%s'", av[3]);
+			vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
 			return;
 		}
 	}
@@ -482,7 +482,7 @@ cmd_logexp_expect(CMD_ARGS)
 	if (av[4]) {
 		vre = VRE_compile(av[4], 0, &err, &pos);
 		if (vre == NULL) {
-			vtc_log(vl, 0, "Regex error (%s): '%s' pos %d",
+			vtc_fatal(vl, "Regex error (%s): '%s' pos %d",
 			    err, av[4], pos);
 			return;
 		}
@@ -559,7 +559,7 @@ cmd_logexpect(CMD_ARGS)
 			break;
 		if (!strcmp(*av, "-wait")) {
 			if (!le->run) {
-				vtc_log(le->vl, 0, "logexp not -started '%s'",
+				vtc_fatal(le->vl, "logexp not -started '%s'",
 					*av);
 				return;
 			}
@@ -577,7 +577,7 @@ cmd_logexpect(CMD_ARGS)
 
 		if (!strcmp(*av, "-v")) {
 			if (av[1] == NULL) {
-				vtc_log(le->vl, 0, "Missing -v argument");
+				vtc_fatal(le->vl, "Missing -v argument");
 				return;
 			}
 			if (le->n_arg != NULL)
@@ -595,7 +595,7 @@ cmd_logexpect(CMD_ARGS)
 		}
 		if (!strcmp(*av, "-d")) {
 			if (av[1] == NULL) {
-				vtc_log(le->vl, 0, "Missing -d argument");
+				vtc_fatal(le->vl, "Missing -d argument");
 				return;
 			}
 			le->d_arg = atoi(av[1]);
@@ -604,12 +604,12 @@ cmd_logexpect(CMD_ARGS)
 		}
 		if (!strcmp(*av, "-g")) {
 			if (av[1] == NULL) {
-				vtc_log(le->vl, 0, "Missing -g argument");
+				vtc_fatal(le->vl, "Missing -g argument");
 				return;
 			}
 			le->g_arg = VSLQ_Name2Grouping(av[1], strlen(av[1]));
 			if (le->g_arg < 0) {
-				vtc_log(le->vl, 0, "Unknown grouping '%s'",
+				vtc_fatal(le->vl, "Unknown grouping '%s'",
 				    av[1]);
 				return;
 			}
@@ -618,7 +618,7 @@ cmd_logexpect(CMD_ARGS)
 		}
 		if (!strcmp(*av, "-q")) {
 			if (av[1] == NULL) {
-				vtc_log(le->vl, 0, "Missing -q argument");
+				vtc_fatal(le->vl, "Missing -q argument");
 				return;
 			}
 			REPLACE(le->query, av[1]);
@@ -640,10 +640,10 @@ cmd_logexpect(CMD_ARGS)
 					av++;
 					continue;
 				}
-				vtc_log(le->vl, 0, "%s", VSL_Error(le->vsl));
+				vtc_fatal(le->vl, "%s", VSL_Error(le->vsl));
 				return;
 			}
-			vtc_log(le->vl, 0, "Unknown logexp argument: %s", *av);
+			vtc_fatal(le->vl, "Unknown logexp argument: %s", *av);
 			return;
 		}
 		logexp_spec(le, *av);
diff --git a/bin/varnishtest/vtc_process.c b/bin/varnishtest/vtc_process.c
index af07779..f8209ff 100644
--- a/bin/varnishtest/vtc_process.c
+++ b/bin/varnishtest/vtc_process.c
@@ -114,7 +114,7 @@ process_new(const char *name)
 	p->fd_from = -1;
 
 	if (*p->name != 'p')
-		vtc_log(p->vl, 0, "Process name must start with 'p'");
+		vtc_fatal(p->vl, "Process name must start with 'p'");
 
 	VTAILQ_INSERT_TAIL(&processes, p, list);
 	return (p);
@@ -219,7 +219,7 @@ process_start(struct process *p)
 
 	CHECK_OBJ_NOTNULL(p, PROCESS_MAGIC);
 	if (p->hasthread)
-		vtc_log(p->vl, 0, "Already running, (-wait first)");
+		vtc_fatal(p->vl, "Already running, (-wait first)");
 
 	vtc_log(p->vl, 4, "CMD: %s", p->spec);
 
@@ -306,7 +306,7 @@ process_kill(struct process *p, const char *sig)
 	AZ(pthread_mutex_unlock(&p->mtx));
 
 	if (pid <= 0)
-		vtc_log(p->vl, 0, "Cannot signal a non-running process");
+		vtc_fatal(p->vl, "Cannot signal a non-running process");
 
 	if (!strcmp(sig, "TERM"))
 		j = SIGTERM;
@@ -317,10 +317,10 @@ process_kill(struct process *p, const char *sig)
 	else if (*sig == '-')
 		j = strtoul(sig + 1, NULL, 10);
 	else
-		vtc_log(p->vl, 0, "Could not grok signal (%s)", sig);
+		vtc_fatal(p->vl, "Could not grok signal (%s)", sig);
 
 	if (kill(-pid, j) < 0)
-		vtc_log(p->vl, 0, "Failed to send signal %d (%s)",
+		vtc_fatal(p->vl, "Failed to send signal %d (%s)",
 		    j, strerror(errno));
 	else
 		vtc_log(p->vl, 4, "Sent signal %d", j);
@@ -346,13 +346,13 @@ process_write(const struct process *p, const char *text)
 	int r, len;
 
 	if (!p->hasthread)
-		vtc_log(p->vl, 0, "Cannot write to a non-running process");
+		vtc_fatal(p->vl, "Cannot write to a non-running process");
 
 	len = strlen(text);
 	vtc_log(p->vl, 4, "Writing %d bytes", len);
 	r = write(p->fd_to, text, len);
 	if (r < 0)
-		vtc_log(p->vl, 0, "Failed to write: %s (%d)",
+		vtc_fatal(p->vl, "Failed to write: %s (%d)",
 		    strerror(errno), errno);
 }
 
@@ -361,7 +361,7 @@ process_close(struct process *p)
 {
 
 	if (!p->hasthread)
-		vtc_log(p->vl, 0, "Cannot close on a non-running process");
+		vtc_fatal(p->vl, "Cannot close on a non-running process");
 
 	AZ(pthread_mutex_lock(&p->mtx));
 	if (p->fd_to >= 0)
@@ -492,7 +492,7 @@ cmd_process(CMD_ARGS)
 			continue;
 		}
 		if (**av == '-')
-			vtc_log(p->vl, 0, "Unknown process argument: %s", *av);
+			vtc_fatal(p->vl, "Unknown process argument: %s", *av);
 		REPLACE(p->spec, *av);
 	}
 }
diff --git a/bin/varnishtest/vtc_server.c b/bin/varnishtest/vtc_server.c
index 377fd1a..c1ad16b 100644
--- a/bin/varnishtest/vtc_server.c
+++ b/bin/varnishtest/vtc_server.c
@@ -126,7 +126,7 @@ server_listen(struct server *s)
 		VTCP_close(&s->sock);
 	s->sock = VTCP_listen_on(s->listen, "0", s->depth, &err);
 	if (err != NULL)
-		vtc_log(s->vl, 0,
+		vtc_fatal(s->vl,
 		    "Server listen address (%s) cannot be resolved: %s",
 		    s->listen, err);
 	assert(s->sock > 0);
@@ -166,13 +166,13 @@ server_thread(void *priv)
 		l = sizeof addr_s;
 		fd = accept(s->sock, addr, &l);
 		if (fd < 0)
-			vtc_log(vl, 0, "Accept failed: %s", strerror(errno));
+			vtc_fatal(vl, "Accept failed: %s", strerror(errno));
 		vtc_log(vl, 3, "accepted fd %d", fd);
 		fd = http_process(vl, s->spec, fd, &s->sock);
 		vtc_log(vl, 3, "shutting fd %d", fd);
 		j = shutdown(fd, SHUT_WR);
 		if (!VTCP_Check(j))
-			vtc_log(vl, 0, "Shutdown failed: %s", strerror(errno));
+			vtc_fatal(vl, "Shutdown failed: %s", strerror(errno));
 		VTCP_close(&fd);
 	}
 	vtc_log(vl, 2, "Ending");
@@ -217,7 +217,7 @@ server_dispatch_wrk(void *priv)
 	vtc_log(vl, 3, "shutting fd %d", fd);
 	j = shutdown(fd, SHUT_WR);
 	if (!VTCP_Check(j))
-		vtc_log(vl, 0, "Shutdown failed: %s", strerror(errno));
+		vtc_fatal(vl, "Shutdown failed: %s", strerror(errno));
 	VTCP_close(&s->fd);
 	vtc_log(vl, 2, "Ending");
 	return (NULL);
@@ -245,7 +245,7 @@ server_dispatch_thread(void *priv)
 		l = sizeof addr_s;
 		fd = accept(s->sock, addr, &l);
 		if (fd < 0)
-			vtc_log(vl, 0, "Accepted failed: %s", strerror(errno));
+			vtc_fatal(vl, "Accepted failed: %s", strerror(errno));
 		bprintf(snbuf, "s%d", sn++);
 		vtc_log(vl, 3, "dispatch fd %d -> %s", fd, snbuf);
 		s2 = server_new(snbuf);
@@ -298,7 +298,7 @@ server_wait(struct server *s)
 	vtc_log(s->vl, 2, "Waiting for server (%d/%d)", s->sock, s->fd);
 	AZ(pthread_join(s->tp, &res));
 	if (res != NULL && !vtc_stop)
-		vtc_log(s->vl, 0, "Server returned \"%p\"",
+		vtc_fatal(s->vl, "Server returned \"%p\"",
 		    (char *)res);
 	s->tp = 0;
 	s->run = 0;
@@ -382,7 +382,7 @@ cmd_server(CMD_ARGS)
 			break;
 		if (!strcmp(*av, "-wait")) {
 			if (!s->run)
-				vtc_log(s->vl, 0, "Server not -started");
+				vtc_fatal(s->vl, "Server not -started");
 			server_wait(s);
 			continue;
 		}
@@ -426,7 +426,7 @@ cmd_server(CMD_ARGS)
 			continue;
 		}
 		if (**av == '-')
-			vtc_log(s->vl, 0, "Unknown server argument: %s", *av);
+			vtc_fatal(s->vl, "Unknown server argument: %s", *av);
 		s->spec = *av;
 	}
 }
diff --git a/bin/varnishtest/vtc_varnish.c b/bin/varnishtest/vtc_varnish.c
index 9ca75ed..1bc8789 100644
--- a/bin/varnishtest/vtc_varnish.c
+++ b/bin/varnishtest/vtc_varnish.c
@@ -108,16 +108,16 @@ varnish_ask_cli(const struct varnish *v, const char *cmd, char **repl)
 		vtc_dump(v->vl, 4, "CLI TX", cmd, -1);
 		i = write(v->cli_fd, cmd, strlen(cmd));
 		if (i != strlen(cmd))
-			vtc_log(v->vl, 0, "CLI write failed (%s) = %u %s",
+			vtc_fatal(v->vl, "CLI write failed (%s) = %u %s",
 			    cmd, errno, strerror(errno));
 		i = write(v->cli_fd, "\n", 1);
 		if (i != 1)
-			vtc_log(v->vl, 0, "CLI write failed (%s) = %u %s",
+			vtc_fatal(v->vl, "CLI write failed (%s) = %u %s",
 			    cmd, errno, strerror(errno));
 	}
 	i = VCLI_ReadResult(v->cli_fd, &retval, &r, vtc_maxdur);
 	if (i != 0) {
-		vtc_log(v->vl, 0, "CLI failed (%s) = %d %u %s",
+		vtc_fatal(v->vl, "CLI failed (%s) = %d %u %s",
 		    cmd, i, retval, r);
 		return ((enum VCLI_status_e)retval);
 	}
@@ -145,7 +145,7 @@ wait_stopped(const struct varnish *v)
 		vtc_log(v->vl, 3, "wait-stopped");
 		st = varnish_ask_cli(v, "status", &r);
 		if (st != CLIS_OK)
-			vtc_log(v->vl, 0,
+			vtc_fatal(v->vl,
 			    "CLI status command failed: %u %s", st, r);
 		if (!strcmp(r, "Child in state stopped")) {
 			free(r);
@@ -170,10 +170,10 @@ wait_running(const struct varnish *v)
 		vtc_log(v->vl, 3, "wait-running");
 		st = varnish_ask_cli(v, "status", &r);
 		if (st != CLIS_OK)
-			vtc_log(v->vl, 0,
+			vtc_fatal(v->vl,
 			    "CLI status command failed: %u %s", st, r);
 		if (!strcmp(r, "Child in state stopped")) {
-			vtc_log(v->vl, 0,
+			vtc_fatal(v->vl,
 			    "Child stopped before running: %u %s", st, r);
 			free(r);
 			break;
@@ -313,7 +313,7 @@ varnish_new(const char *name)
 	AZ(system(buf));
 
 	if (*v->name != 'v')
-		vtc_log(v->vl, 0, "Varnish name must start with 'v'");
+		vtc_fatal(v->vl, "Varnish name must start with 'v'");
 
 	v->args = VSB_new_auto();
 
@@ -406,7 +406,7 @@ varnish_launch(struct varnish *v)
 	/* Create listener socket */
 	v->cli_fd = VTCP_listen_on("127.0.0.1:0", NULL, 1, &err);
 	if (err != NULL)
-		vtc_log(v->vl, 0, "Create CLI listen socket failed: %s", err);
+		vtc_fatal(v->vl, "Create CLI listen socket failed: %s", err);
 	assert(v->cli_fd > 0);
 	VTCP_myname(v->cli_fd, abuf, sizeof abuf, pbuf, sizeof pbuf);
 
@@ -481,19 +481,19 @@ varnish_launch(struct varnish *v)
 	vtc_log(v->vl, 4, "CLIPOLL %d 0x%x 0x%x",
 	    i, fd[0].revents, fd[1].revents);
 	if (i == 0) {
-		vtc_log(v->vl, 0, "FAIL timeout waiting for CLI connection");
+		vtc_fatal(v->vl, "FAIL timeout waiting for CLI connection");
 		AZ(close(v->cli_fd));
 		v->cli_fd = -1;
 		return;
 	}
 	if (fd[1].revents & POLLHUP) {
-		vtc_log(v->vl, 0, "FAIL debug pipe closed");
+		vtc_fatal(v->vl, "FAIL debug pipe closed");
 		AZ(close(v->cli_fd));
 		v->cli_fd = -1;
 		return;
 	}
 	if (!(fd[0].revents & POLLIN)) {
-		vtc_log(v->vl, 0, "FAIL CLI connection wait failure");
+		vtc_fatal(v->vl, "FAIL CLI connection wait failure");
 		AZ(close(v->cli_fd));
 		v->cli_fd = -1;
 		return;
@@ -502,7 +502,7 @@ varnish_launch(struct varnish *v)
 	if (nfd < 0) {
 		AZ(close(v->cli_fd));
 		v->cli_fd = -1;
-		vtc_log(v->vl, 0, "FAIL no CLI connection accepted");
+		vtc_fatal(v->vl, "FAIL no CLI connection accepted");
 		return;
 	}
 
@@ -517,7 +517,7 @@ varnish_launch(struct varnish *v)
 	if (vtc_error)
 		return;
 	if (u != CLIS_AUTH)
-		vtc_log(v->vl, 0, "CLI auth demand expected: %u %s", u, r);
+		vtc_fatal(v->vl, "CLI auth demand expected: %u %s", u, r);
 
 	bprintf(abuf, "%s/_.secret", v->workdir);
 	nfd = open(abuf, O_RDONLY);
@@ -535,7 +535,7 @@ varnish_launch(struct varnish *v)
 	if (vtc_error)
 		return;
 	if (u != CLIS_OK)
-		vtc_log(v->vl, 0, "CLI auth command failed: %u %s", u, r);
+		vtc_fatal(v->vl, "CLI auth command failed: %u %s", u, r);
 	free(r);
 
 	(void)VSM_n_Arg(v->vd, v->workdir);
@@ -561,7 +561,7 @@ varnish_start(struct varnish *v)
 	if (vtc_error)
 		return;
 	if (u != CLIS_OK)
-		vtc_log(v->vl, 0, "CLI start command failed: %u %s", u, resp);
+		vtc_fatal(v->vl, "CLI start command failed: %u %s", u, resp);
 	wait_running(v);
 	free(resp);
 	resp = NULL;
@@ -569,7 +569,7 @@ varnish_start(struct varnish *v)
 	if (vtc_error)
 		return;
 	if (u != CLIS_OK)
-		vtc_log(v->vl, 0, "CLI debug.xid command failed: %u %s",
+		vtc_fatal(v->vl, "CLI debug.xid command failed: %u %s",
 		    u, resp);
 	free(resp);
 	resp = NULL;
@@ -577,7 +577,7 @@ varnish_start(struct varnish *v)
 	if (vtc_error)
 		return;
 	if (u != CLIS_OK)
-		vtc_log(v->vl, 0,
+		vtc_fatal(v->vl,
 		    "CLI debug.listen_address command failed: %u %s", u, resp);
 	h = resp;
 	p = strchr(h, '\n');
@@ -661,11 +661,11 @@ varnish_cleanup(struct varnish *v)
 	if (WIFEXITED(status) && (WEXITSTATUS(status) == 0))
 		return;
 #ifdef WCOREDUMP
-	vtc_log(v->vl, 0, "Bad exit code: %04x sig %x exit %x core %x",
+	vtc_fatal(v->vl, "Bad exit code: %04x sig %x exit %x core %x",
 	    status, WTERMSIG(status), WEXITSTATUS(status),
 	    WCOREDUMP(status));
 #else
-	vtc_log(v->vl, 0, "Bad exit code: %04x sig %x exit %x",
+	vtc_fatal(v->vl, "Bad exit code: %04x sig %x exit %x",
 	    status, WTERMSIG(status), WEXITSTATUS(status));
 #endif
 }
@@ -710,7 +710,7 @@ varnish_cli(struct varnish *v, const char *cli, unsigned exp, const char *re)
 	if (re != NULL) {
 		vre = VRE_compile(re, 0, &errptr, &err);
 		if (vre == NULL)
-			vtc_log(v->vl, 0, "Illegal regexp");
+			vtc_fatal(v->vl, "Illegal regexp");
 	}
 	if (v->cli_fd < 0)
 		varnish_launch(v);
@@ -719,11 +719,11 @@ varnish_cli(struct varnish *v, const char *cli, unsigned exp, const char *re)
 	u = varnish_ask_cli(v, cli, &resp);
 	vtc_log(v->vl, 2, "CLI %03u <%s>", u, cli);
 	if (exp != 0 && exp != (unsigned)u)
-		vtc_log(v->vl, 0, "FAIL CLI response %u expected %u", u, exp);
+		vtc_fatal(v->vl, "FAIL CLI response %u expected %u", u, exp);
 	if (vre != NULL) {
 		err = VRE_exec(vre, resp, strlen(resp), 0, 0, NULL, 0, NULL);
 		if (err < 1)
-			vtc_log(v->vl, 0, "Expect failed (%d)", err);
+			vtc_fatal(v->vl, "Expect failed (%d)", err);
 		VRE_free(&vre);
 	}
 }
@@ -752,7 +752,7 @@ varnish_vcl(struct varnish *v, const char *vcl, int fail, char **resp)
 	u = varnish_ask_cli(v, VSB_data(vsb), resp);
 	if (u == CLIS_OK && fail) {
 		VSB_destroy(&vsb);
-		vtc_log(v->vl, 0,
+		vtc_fatal(v->vl,
 		    "VCL compilation succeeded expected failure");
 		return;
 	} else if (u == CLIS_OK) {
@@ -763,7 +763,7 @@ varnish_vcl(struct varnish *v, const char *vcl, int fail, char **resp)
 		assert(u == CLIS_OK);
 	} else if (!fail) {
 		VSB_destroy(&vsb);
-		vtc_log(v->vl, 0,
+		vtc_fatal(v->vl,
 		    "VCL compilation failed expected success");
 		return;
 	} else {
@@ -806,7 +806,7 @@ varnish_vclbackend(struct varnish *v, const char *vcl)
 	if (u != CLIS_OK) {
 		VSB_destroy(&vsb);
 		VSB_destroy(&vsb2);
-		vtc_log(v->vl, 0, "FAIL VCL does not compile");
+		vtc_fatal(v->vl, "FAIL VCL does not compile");
 		return;
 	}
 	VSB_clear(vsb);
@@ -968,14 +968,14 @@ varnish_expect(const struct varnish *v, char * const *av)
 		}
 
 		if (not) {
-			vtc_log(v->vl, 0, "Found (not expected): %s", av[0]+1);
+			vtc_fatal(v->vl, "Found (not expected): %s", av[0]+1);
 			return;
 		}
 
 		good = 0;
 		ref = strtoumax(av[2], &p, 0);
 		if (ref == UINTMAX_MAX || *p)
-			vtc_log(v->vl, 0, "Syntax error in number (%s)", av[2]);
+			vtc_fatal(v->vl, "Syntax error in number (%s)", av[2]);
 		if      (!strcmp(av[1], "==")) { if (sp.val == ref) good = 1; }
 		else if (!strcmp(av[1], "!=")) { if (sp.val != ref) good = 1; }
 		else if (!strcmp(av[1], ">"))  { if (sp.val > ref)  good = 1; }
@@ -983,13 +983,13 @@ varnish_expect(const struct varnish *v, char * const *av)
 		else if (!strcmp(av[1], ">=")) { if (sp.val >= ref) good = 1; }
 		else if (!strcmp(av[1], "<=")) { if (sp.val <= ref) good = 1; }
 		else {
-			vtc_log(v->vl, 0, "comparison %s unknown", av[1]);
+			vtc_fatal(v->vl, "comparison %s unknown", av[1]);
 		}
 		if (good)
 			break;
 	}
 	if (good == -1) {
-		vtc_log(v->vl, 0, "VSM error: %s", VSM_Error(v->vd));
+		vtc_fatal(v->vl, "VSM error: %s", VSM_Error(v->vd));
 	}
 	if (good == -2) {
 		if (not) {
@@ -997,14 +997,14 @@ varnish_expect(const struct varnish *v, char * const *av)
 			    av[0] + 1);
 			return;
 		}
-		vtc_log(v->vl, 0, "stats field %s unknown", av[0]);
+		vtc_fatal(v->vl, "stats field %s unknown", av[0]);
 	}
 
 	if (good == 1) {
 		vtc_log(v->vl, 2, "as expected: %s (%ju) %s %s",
 		    av[0], sp.val, av[1], av[2]);
 	} else {
-		vtc_log(v->vl, 0, "Not true: %s (%ju) %s %s (%ju)",
+		vtc_fatal(v->vl, "Not true: %s (%ju) %s %s (%ju)",
 		    av[0], (uintmax_t)sp.val, av[1], av[2], (uintmax_t)ref);
 	}
 }
@@ -1177,7 +1177,7 @@ cmd_varnish(CMD_ARGS)
 			AN(av[2]);
 			varnish_vcl(v, av[2], 1, &r);
 			if (strstr(r, av[1]) == NULL)
-				vtc_log(v->vl, 0,
+				vtc_fatal(v->vl,
 				    "Did not find expected string: (\"%s\")",
 				    av[1]);
 			else
@@ -1252,6 +1252,6 @@ cmd_varnish(CMD_ARGS)
 			varnish_wait(v);
 			continue;
 		}
-		vtc_log(v->vl, 0, "Unknown varnish argument: %s", *av);
+		vtc_fatal(v->vl, "Unknown varnish argument: %s", *av);
 	}
 }



More information about the varnish-commit mailing list