[master] d604cdbaa Give HTTP2 streams their own log + identifier on the form "[cs]%d.%d"

Poul-Henning Kamp phk at FreeBSD.org
Mon Oct 19 08:35:07 UTC 2020


commit d604cdbaac4073be48aef78b47474cd902a84b7c
Author: Poul-Henning Kamp <phk at FreeBSD.org>
Date:   Mon Oct 19 08:33:32 2020 +0000

    Give HTTP2 streams their own log + identifier on the form "[cs]%d.%d"

diff --git a/bin/varnishtest/vtc.h b/bin/varnishtest/vtc.h
index af2d37bd7..9983527db 100644
--- a/bin/varnishtest/vtc.h
+++ b/bin/varnishtest/vtc.h
@@ -115,7 +115,7 @@ void cmd_server_gen_vcl(struct vsb *vsb);
 void cmd_server_gen_haproxy_conf(struct vsb *vsb);
 
 void vtc_loginit(char *buf, unsigned buflen);
-struct vtclog *vtc_logopen(const char *id);
+struct vtclog *vtc_logopen(const char *id, ...) v_printflike_(1, 2);
 void vtc_logclose(void *arg);
 void vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
     v_printflike_(3, 4);
diff --git a/bin/varnishtest/vtc_barrier.c b/bin/varnishtest/vtc_barrier.c
index 4eccf309d..6af18d252 100644
--- a/bin/varnishtest/vtc_barrier.c
+++ b/bin/varnishtest/vtc_barrier.c
@@ -137,7 +137,7 @@ barrier_sock_thread(void *priv)
 
 	AZ(pthread_mutex_lock(&b->mtx));
 
-	vl = vtc_logopen(b->name);
+	vl = vtc_logopen("%s", b->name);
 	pthread_cleanup_push(vtc_logclose, vl);
 
 	sock = VTCP_listen_on("127.0.0.1:0", NULL, b->expected, &err);
diff --git a/bin/varnishtest/vtc_client.c b/bin/varnishtest/vtc_client.c
index 41cc3a581..ab22147f5 100644
--- a/bin/varnishtest/vtc_client.c
+++ b/bin/varnishtest/vtc_client.c
@@ -233,7 +233,7 @@ client_new(const char *name)
 	ALLOC_OBJ(c, CLIENT_MAGIC);
 	AN(c);
 	REPLACE(c->name, name);
-	c->vl = vtc_logopen(name);
+	c->vl = vtc_logopen("%s", name);
 	AN(c->vl);
 	c->vsp = Sess_New(c->vl, name);
 	AN(c->vsp);
diff --git a/bin/varnishtest/vtc_haproxy.c b/bin/varnishtest/vtc_haproxy.c
index c650f81b5..b42831798 100644
--- a/bin/varnishtest/vtc_haproxy.c
+++ b/bin/varnishtest/vtc_haproxy.c
@@ -565,7 +565,7 @@ haproxy_new(const char *name)
 
 	h->args = VSB_new_auto();
 
-	h->vl = vtc_logopen(name);
+	h->vl = vtc_logopen("%s", name);
 	AN(h->vl);
 
 	h->filename = getenv(HAPROXY_PROGRAM_ENV_VAR);
diff --git a/bin/varnishtest/vtc_http2.c b/bin/varnishtest/vtc_http2.c
index ebf17d23a..fda5143e0 100644
--- a/bin/varnishtest/vtc_http2.c
+++ b/bin/varnishtest/vtc_http2.c
@@ -93,6 +93,7 @@ struct stream {
 	unsigned		magic;
 #define STREAM_MAGIC		0x63f1fac2
 	uint32_t		id;
+	struct vtclog		*vl;
 	char			*spec;
 	char			*name;
 	VTAILQ_ENTRY(stream)    list;
@@ -134,14 +135,14 @@ clean_headers(struct hpk_hdr *h)
 #define ONLY_H2_CLIENT(hp, av)						\
 	do {								\
 		if (hp->sfd != NULL)					\
-			vtc_fatal(hp->vl,				\
+			vtc_fatal(s->vl,				\
 			    "\"%s\" only possible in client", av[0]);	\
 	} while (0)
 
 #define ONLY_H2_SERVER(hp, av)						\
 	do {								\
 		if (hp->sfd == NULL)					\
-			vtc_fatal(hp->vl,				\
+			vtc_fatal(s->vl,				\
 			    "\"%s\" only possible in server", av[0]);	\
 	} while (0)
 
@@ -316,17 +317,20 @@ clean_frame(struct frame **fp)
 }
 
 static void
-write_frame(struct http *hp, const struct frame *f, const unsigned lock)
+write_frame(const struct stream *sp, const struct frame *f, const unsigned lock)
 {
+	struct http *hp;
 	ssize_t l;
 	char hdr[9];
 
+	CHECK_OBJ_NOTNULL(sp, STREAM_MAGIC);
+	hp = sp->hp;
 	CHECK_OBJ_NOTNULL(hp, HTTP_MAGIC);
 	CHECK_OBJ_NOTNULL(f, FRAME_MAGIC);
 
 	writeFrameHeader(hdr, f);
 
-	vtc_log(hp->vl, 3, "tx: stream: %d, type: %s (%d), "
+	vtc_log(sp->vl, 3, "tx: stream: %d, type: %s (%d), "
 			"flags: 0x%02x, size: %d",
 			f->stid,
 			f->type < TYPE_MAX ? h2_types[f->type] : "?",
@@ -336,14 +340,14 @@ write_frame(struct http *hp, const struct frame *f, const unsigned lock)
 		AZ(pthread_mutex_lock(&hp->mtx));
 	l = write(hp->sess->fd, hdr, sizeof(hdr));
 	if (l != sizeof(hdr))
-		vtc_log(hp->vl, hp->fatal, "Write failed: (%zd vs %zd) %s",
+		vtc_log(sp->vl, hp->fatal, "Write failed: (%zd vs %zd) %s",
 		    l, sizeof(hdr), strerror(errno));
 
 	if (f->size) {
 		AN(f->data);
 		l = write(hp->sess->fd, f->data, f->size);
 		if (l != f->size)
-			vtc_log(hp->vl, hp->fatal,
+			vtc_log(sp->vl, hp->fatal,
 					"Write failed: (%zd vs %d) %s",
 					l, f->size, strerror(errno));
 	}
@@ -401,7 +405,7 @@ parse_data(struct stream *s, struct frame *f)
 	if (f->flags & PADDED) {
 		f->md.padded = *((uint8_t *)data);
 		if (f->md.padded >= size) {
-			vtc_log(hp->vl, hp->fatal,
+			vtc_log(s->vl, hp->fatal,
 					"invalid padding: %d reported,"
 					"but size is only %d",
 					f->md.padded, size);
@@ -410,7 +414,7 @@ parse_data(struct stream *s, struct frame *f)
 		}
 		data++;
 		size -= f->md.padded + 1;
-		vtc_log(hp->vl, 4, "padding: %3d", f->md.padded);
+		vtc_log(s->vl, 4, "padding: %3d", f->md.padded);
 	}
 
 	if (s->id)
@@ -420,7 +424,7 @@ parse_data(struct stream *s, struct frame *f)
 
 	if (!size) {
 		AZ(data);
-		vtc_log(hp->vl, 4, "s%u - no data", s->id);
+		vtc_log(s->vl, 4, "s%u - no data", s->id);
 		return;
 	}
 
@@ -491,7 +495,7 @@ parse_hdr(struct stream *s, struct frame *f, struct vsb *vsb)
 	if (f->flags & PADDED && f->type != TYPE_CONTINUATION) {
 		f->md.padded = *((uint8_t *)data);
 		if (f->md.padded >= size) {
-			vtc_log(hp->vl, hp->fatal,
+			vtc_log(s->vl, hp->fatal,
 					"invalid padding: %d reported,"
 					"but size is only %d",
 					f->md.padded, size);
@@ -500,7 +504,7 @@ parse_hdr(struct stream *s, struct frame *f, struct vsb *vsb)
 		}
 		shift += 1;
 		size -= f->md.padded;
-		vtc_log(hp->vl, 4, "padding: %3d", f->md.padded);
+		vtc_log(s->vl, 4, "padding: %3d", f->md.padded);
 	}
 
 	if (f->type == TYPE_HEADERS && f->flags & PRIORITY){
@@ -513,8 +517,8 @@ parse_hdr(struct stream *s, struct frame *f, struct vsb *vsb)
 		if (exclusive)
 			exclusive_stream_dependency(s);
 
-		vtc_log(hp->vl, 4, "stream->dependency: %u", s->dependency);
-		vtc_log(hp->vl, 4, "stream->weight: %u", s->weight);
+		vtc_log(s->vl, 4, "stream->dependency: %u", s->dependency);
+		vtc_log(s->vl, 4, "stream->weight: %u", s->weight);
 	} else if (f->type == TYPE_PUSH_PROMISE){
 		shift += 4;
 		n = vbe32dec(f->data);
@@ -536,7 +540,7 @@ parse_prio(struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 5)
-		vtc_fatal(hp->vl, "Size should be 5, but isn't (%d)", f->size);
+		vtc_fatal(s->vl, "Size should be 5, but isn't (%d)", f->size);
 
 	buf = f->data;
 	AN(buf);
@@ -554,8 +558,8 @@ parse_prio(struct stream *s, struct frame *f)
 	f->md.prio.weight = *buf;
 	s->weight = f->md.prio.weight;
 
-	vtc_log(hp->vl, 3, "prio->stream: %u", f->md.prio.stream);
-	vtc_log(hp->vl, 3, "prio->weight: %u", f->md.prio.weight);
+	vtc_log(s->vl, 3, "prio->stream: %u", f->md.prio.stream);
+	vtc_log(s->vl, 3, "prio->weight: %u", f->md.prio.weight);
 }
 
 static void
@@ -569,17 +573,17 @@ parse_rst(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 4)
-		vtc_fatal(hp->vl, "Size should be 4, but isn't (%d)", f->size);
+		vtc_fatal(s->vl, "Size should be 4, but isn't (%d)", f->size);
 
 	err = vbe32dec(f->data);
 	f->md.rst_err = err;
 
-	vtc_log(hp->vl, 2, "ouch");
+	vtc_log(s->vl, 2, "ouch");
 	if (err <= ERR_MAX)
 		buf = h2_errs[err];
 	else
 		buf = "unknown";
-	vtc_log(hp->vl, 4, "rst->err: %s (%d)", buf, err);
+	vtc_log(s->vl, 4, "rst->err: %s (%d)", buf, err);
 
 }
 
@@ -596,7 +600,7 @@ parse_settings(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size % 6)
-		vtc_fatal(hp->vl,
+		vtc_fatal(s->vl,
 		    "Size should be a multiple of 6, but isn't (%d)", f->size);
 
 	for (u = 0; u <= SETTINGS_MAX; u++)
@@ -618,7 +622,7 @@ parse_settings(const struct stream *s, struct frame *f)
 			assert(r == hpk_done);
 		}
 
-		vtc_log(hp->vl, 4, "settings->%s (%u): %d", buf, t, v);
+		vtc_log(s->vl, 4, "settings->%s (%u): %d", buf, t, v);
 	}
 
 }
@@ -631,12 +635,12 @@ 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_fatal(hp->vl, "Size should be 8, but isn't (%d)", f->size);
+		vtc_fatal(s->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';
 
-	vtc_log(hp->vl, 4, "ping->data: %s", f->md.ping.data);
+	vtc_log(s->vl, 4, "ping->data: %s", f->md.ping.data);
 
 }
 
@@ -651,10 +655,10 @@ parse_goaway(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size < 8)
-		vtc_fatal(hp->vl,
+		vtc_fatal(s->vl,
 		    "Size should be at least 8, but isn't (%d)", f->size);
 	if (f->data[0] & (1<<7))
-		vtc_fatal(hp->vl,
+		vtc_fatal(s->vl,
 		    "First bit of data is reserved and should be 0");
 
 	stid = vbe32dec(f->data);
@@ -675,10 +679,10 @@ parse_goaway(const struct stream *s, struct frame *f)
 		memcpy(f->md.goaway.debug, f->data + 8, f->size - 8);
 	}
 
-	vtc_log(hp->vl, 3, "goaway->laststream: %d", stid);
-	vtc_log(hp->vl, 3, "goaway->err: %s (%d)", err_buf, err);
+	vtc_log(s->vl, 3, "goaway->laststream: %d", stid);
+	vtc_log(s->vl, 3, "goaway->err: %s (%d)", err_buf, err);
 	if (f->md.goaway.debug)
-		vtc_log(hp->vl, 3, "goaway->debug: %s", f->md.goaway.debug);
+		vtc_log(s->vl, 3, "goaway->debug: %s", f->md.goaway.debug);
 }
 
 static void
@@ -691,15 +695,15 @@ parse_winup(const struct stream *s, struct frame *f)
 	CAST_OBJ_NOTNULL(hp, s->hp, HTTP_MAGIC);;
 
 	if (f->size != 4)
-		vtc_fatal(hp->vl, "Size should be 4, but isn't (%d)", f->size);
+		vtc_fatal(s->vl, "Size should be 4, but isn't (%d)", f->size);
 	if (f->data[0] & (1<<7))
-		vtc_log(hp->vl, s->hp->fatal,
+		vtc_log(s->vl, s->hp->fatal,
 		    "First bit of data is reserved and should be 0");
 
 	size = vbe32dec(f->data);
 	f->md.winup_size = size;
 
-	vtc_log(hp->vl, 3, "winup->size: %d", size);
+	vtc_log(s->vl, 3, "winup->size: %d", size);
 }
 
 /* read a frame and queue it in the relevant stream, wait if not present yet.
@@ -780,9 +784,10 @@ receive_frame(void *priv)
 		}
 		AZ(pthread_mutex_unlock(&hp->mtx));
 
+		AN(s);
 		if (expect_cont &&
 		    (f->type != TYPE_CONTINUATION || expect_cont != s->id))
-			vtc_fatal(hp->vl, "Expected CONTINUATION frame for "
+			vtc_fatal(s->vl, "Expected CONTINUATION frame for "
 			    "stream %u", expect_cont);
 
 		/* parse the frame according to it type, and fill the metada */
@@ -875,7 +880,7 @@ do {									\
 
 #define CHECK_LAST_FRAME(TYPE) \
 	if (!f || f->type != TYPE_ ## TYPE) {				   \
-		vtc_fatal(s->hp->vl, "Last frame was not of type " #TYPE); \
+		vtc_fatal(s->vl, "Last frame was not of type " #TYPE); \
 	}
 
 #define RETURN_SETTINGS(idx) \
@@ -1080,7 +1085,7 @@ cmd_var_resolve(const struct stream *s, const char *spec, char *buf)
 	if (!strncmp(spec, "frame.", 6)) {
 		spec += 6;
 		if (!f)
-			vtc_fatal(s->hp->vl, "No frame received yet.");
+			vtc_fatal(s->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); }
@@ -1089,7 +1094,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_fatal(s->hp->vl,
+				vtc_fatal(s->vl,
 						"Last frame was not of type "
 						"DATA, HEADERS or PUSH");
 			RETURN_BUFFED(f->md.padded);
@@ -1645,7 +1650,7 @@ cmd_tx11obj(CMD_ARGS)
 		f.size += 4;
 	f.data = buf;
 	HPK_FreeIter(iter);
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 	free(buf);
 
 	if (!body)
@@ -1654,7 +1659,7 @@ cmd_tx11obj(CMD_ARGS)
 	INIT_FRAME(f, DATA, bodylen, s->id, END_STREAM);
 	f.data = body;
 
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 	free(body);
 }
 
@@ -1739,7 +1744,7 @@ cmd_txdata(CMD_ARGS)
 		f.size = strlen(body);
 		f.data = body;
 	}
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 	free(body);
 	free(pad);
 	free(data);
@@ -1787,7 +1792,7 @@ cmd_txrst(CMD_ARGS)
 
 	err = htonl(err);
 	f.data = (void *)&err;
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 }
 
 /* SECTION: stream.spec.prio_txprio txprio
@@ -1842,7 +1847,7 @@ cmd_txprio(CMD_ARGS)
 
 	vbe32enc(buf, (stid | exclusive));
 	buf[4] = s->weight;
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 }
 
 #define PUT_KV(av, vl, name, val, code) \
@@ -1941,7 +1946,8 @@ cmd_txsettings(CMD_ARGS)
 	if (*av != NULL)
 		vtc_fatal(vl, "Unknown txsettings spec: %s\n", *av);
 
-	write_frame(hp, &f, 0);
+	AN(s->hp);
+	write_frame(s, &f, 0);
 	AZ(pthread_mutex_unlock(&hp->mtx));
 }
 
@@ -1984,7 +1990,7 @@ cmd_txping(CMD_ARGS)
 		vtc_fatal(vl, "Unknown txping spec: %s\n", *av);
 	if (!f.data)
 		f.data = buf;
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 }
 
 /*
@@ -2052,7 +2058,7 @@ cmd_txgoaway(CMD_ARGS)
 	}
 	vbe32enc(f.data, ls);
 	vbe32enc(f.data + 4, err);
-	write_frame(s->hp, &f, 1);
+	write_frame(s, &f, 1);
 	free(f.data);
 }
 
@@ -2101,7 +2107,7 @@ cmd_txwinup(CMD_ARGS)
 
 	size = htonl(size);
 	f.data = (void *)&size;
-	write_frame(hp, &f, 1);
+	write_frame(s, &f, 1);
 }
 
 static struct frame *
@@ -2451,7 +2457,7 @@ cmd_rxframe(CMD_ARGS)
 	(void)av;
 	CAST_OBJ_NOTNULL(s, priv, STREAM_MAGIC);
 	if (rxstuff(s) == NULL)
-		vtc_fatal(s->hp->vl, "No frame received");
+		vtc_fatal(s->vl, "No frame received");
 }
 
 static void
@@ -2523,7 +2529,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_fatal(s->hp->vl, "failed to write body: %s (%d)",
+		vtc_fatal(s->vl, "failed to write body: %s (%d)",
 		    strerror(errno), errno);
 }
 
@@ -2573,8 +2579,8 @@ stream_thread(void *priv)
 	struct stream *s;
 
 	CAST_OBJ_NOTNULL(s, priv, STREAM_MAGIC);
-	parse_string(s->spec, stream_cmds, s, s->hp->vl);
-	vtc_log(s->hp->vl, 2, "Ending stream %u", s->id);
+	parse_string(s->spec, stream_cmds, s, s->vl);
+	vtc_log(s->vl, 2, "Ending stream %u", s->id);
 	return (NULL);
 }
 /**********************************************************************
@@ -2591,16 +2597,17 @@ stream_new(const char *name, struct http *h)
 	AN(s);
 	AZ(pthread_cond_init(&s->cond, NULL));
 	REPLACE(s->name, name);
-	AN(name);
+	AN(s->name);
 	VTAILQ_INIT(&s->fq);
 	s->ws = h->iws;
+	s->vl = vtc_logopen("%s.%s", h->sess->name, name);
 
 	s->weight = 16;
 	s->dependency = 0;
 
-	STRTOU32(s->id, name, p, h->vl, "stream");
+	STRTOU32(s->id, name, p, s->vl, "stream");
 	if (s->id & (1U << 31))
-		vtc_fatal(h->vl, "Stream id must be a 31-bits integer "
+		vtc_fatal(s->vl, "Stream id must be a 31-bits integer "
 		    "(found %s)", name);
 
 	CHECK_OBJ_NOTNULL(h, HTTP_MAGIC);
@@ -2628,6 +2635,7 @@ stream_delete(struct stream *s)
 		VTAILQ_REMOVE(&s->fq, f, list);
 		clean_frame(&f);
 	}
+	vtc_logclose(s->vl);
 	clean_headers(s->req);
 	clean_headers(s->resp);
 	AZ(s->frame);
@@ -2645,7 +2653,7 @@ static void
 stream_start(struct stream *s)
 {
 	CHECK_OBJ_NOTNULL(s, STREAM_MAGIC);
-	vtc_log(s->hp->vl, 2, "Starting stream %p", s);
+	vtc_log(s->hp->vl, 2, "Starting stream %s (%p)", s->name, s);
 	AZ(pthread_create(&s->tp, NULL, stream_thread, s));
 	s->running = 1;
 }
diff --git a/bin/varnishtest/vtc_log.c b/bin/varnishtest/vtc_log.c
index 645a5f11a..c60eab94b 100644
--- a/bin/varnishtest/vtc_log.c
+++ b/bin/varnishtest/vtc_log.c
@@ -47,7 +47,7 @@ static unsigned		vtclog_left;
 struct vtclog {
 	unsigned	magic;
 #define VTCLOG_MAGIC	0x82731202
-	const char	*id;
+	char		*id;
 	struct vsb	*vsb;
 	pthread_mutex_t	mtx;
 	int		act;
@@ -77,13 +77,19 @@ static double t0;
 
 
 struct vtclog *
-vtc_logopen(const char *id)
+vtc_logopen(const char *fmt, ...)
 {
 	struct vtclog *vl;
+	va_list ap;
+	char buf[BUFSIZ];
+
+	va_start(ap, fmt);
+	vbprintf(buf, fmt, ap);
+	va_end(ap);
 
 	ALLOC_OBJ(vl, VTCLOG_MAGIC);
 	AN(vl);
-	vl->id = id;
+	REPLACE(vl->id, buf);
 	vl->vsb = VSB_new_auto();
 	AZ(pthread_mutex_init(&vl->mtx, NULL));
 	AZ(pthread_setspecific(log_key, vl));
@@ -100,6 +106,7 @@ vtc_logclose(void *arg)
 		AZ(pthread_setspecific(log_key, NULL));
 	VSB_destroy(&vl->vsb);
 	AZ(pthread_mutex_destroy(&vl->mtx));
+	REPLACE(vl->id, NULL);
 	FREE_OBJ(vl);
 }
 
@@ -130,7 +137,7 @@ vtc_leadinv(const struct vtclog *vl, int lvl, const char *fmt, va_list ap)
 
 	assert(lvl < (int)NLEAD);
 	assert(lvl >= 0);
-	VSB_printf(vl->vsb, "%s %-4s ",
+	VSB_printf(vl->vsb, "%s %-5s ",
 	    lead[lvl < 0 ? 1: lvl], vl->id);
 	if (fmt != NULL)
 		(void)VSB_vprintf(vl->vsb, fmt, ap);
@@ -162,7 +169,7 @@ vtc_log_emit(const struct vtclog *vl)
 	if (t_last != t_this) {
 		assert(vtclog_left > 25);
 		i = snprintf(vtclog_buf, vtclog_left,
-		    "**** dT   %d.%03d\n", t_this / 1000, t_this % 1000);
+		    "**** dT    %d.%03d\n", t_this / 1000, t_this % 1000);
 		t_last = t_this;
 		vtclog_buf += i;
 		vtclog_left -= i;
@@ -224,7 +231,7 @@ vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
 	if (str == NULL)
 		vtc_leadin(vl, lvl, "%s(null)\n", pfx);
 	else {
-		bprintf(buf, "%s %-4s %s|",
+		bprintf(buf, "%s %-5s %s|",
 		    lead[lvl < 0 ? 1: lvl], vl->id, pfx);
 		if (len < 0)
 			len = strlen(str);
diff --git a/bin/varnishtest/vtc_logexp.c b/bin/varnishtest/vtc_logexp.c
index 4719ad034..32a64d7aa 100644
--- a/bin/varnishtest/vtc_logexp.c
+++ b/bin/varnishtest/vtc_logexp.c
@@ -214,7 +214,7 @@ logexp_new(const char *name, const char *varg)
 	ALLOC_OBJ(le, LOGEXP_MAGIC);
 	AN(le);
 	REPLACE(le->name, name);
-	le->vl = vtc_logopen(name);
+	le->vl = vtc_logopen("%s", name);
 	VTAILQ_INIT(&le->tests);
 
 	le->d_arg = 0;
diff --git a/bin/varnishtest/vtc_process.c b/bin/varnishtest/vtc_process.c
index f8ad2baa8..c1b4835d7 100644
--- a/bin/varnishtest/vtc_process.c
+++ b/bin/varnishtest/vtc_process.c
@@ -386,7 +386,7 @@ process_new(const char *name)
 	REPLACE(p->name, name);
 	AZ(pthread_mutex_init(&p->mtx, NULL));
 
-	p->vl = vtc_logopen(name);
+	p->vl = vtc_logopen("%s", name);
 	AN(p->vl);
 
 	PROCESS_EXPAND(dir, "${tmpdir}/%s", name);
diff --git a/bin/varnishtest/vtc_server.c b/bin/varnishtest/vtc_server.c
index 4043c27da..0f44c75c3 100644
--- a/bin/varnishtest/vtc_server.c
+++ b/bin/varnishtest/vtc_server.c
@@ -83,7 +83,7 @@ server_new(const char *name, struct vtclog *vl)
 	ALLOC_OBJ(s, SERVER_MAGIC);
 	AN(s);
 	REPLACE(s->name, name);
-	s->vl = vtc_logopen(s->name);
+	s->vl = vtc_logopen("%s", s->name);
 	AN(s->vl);
 	s->vsp = Sess_New(s->vl, name);
 	AN(s->vsp);
@@ -302,7 +302,7 @@ server_dispatch_wrk(void *priv)
 	CAST_OBJ_NOTNULL(s, priv, SERVER_MAGIC);
 	assert(s->sock < 0);
 
-	vl = vtc_logopen(s->name);
+	vl = vtc_logopen("%s", s->name);
 	pthread_cleanup_push(vtc_logclose, vl);
 
 	fd = s->fd;
@@ -334,7 +334,7 @@ server_dispatch_thread(void *priv)
 	CAST_OBJ_NOTNULL(s, priv, SERVER_MAGIC);
 	assert(s->sock >= 0);
 
-	vl = vtc_logopen(s->name);
+	vl = vtc_logopen("%s", s->name);
 	pthread_cleanup_push(vtc_logclose, vl);
 
 	vtc_log(vl, 2, "Dispatch started on %s", s->listen);
diff --git a/bin/varnishtest/vtc_sess.c b/bin/varnishtest/vtc_sess.c
index f1813e819..d9766bf28 100644
--- a/bin/varnishtest/vtc_sess.c
+++ b/bin/varnishtest/vtc_sess.c
@@ -128,7 +128,7 @@ sess_thread(void *priv)
 
 	vsp = ta.vsp;
 	CHECK_OBJ_NOTNULL(vsp, VTC_SESS_MAGIC);
-	vl = vtc_logopen(vsp->name);
+	vl = vtc_logopen("%s", vsp->name);
 	pthread_cleanup_push(vtc_logclose, vl);
 
 	assert(vsp->repeat > 0);
diff --git a/bin/varnishtest/vtc_syslog.c b/bin/varnishtest/vtc_syslog.c
index c388ac8e6..aa81095f7 100644
--- a/bin/varnishtest/vtc_syslog.c
+++ b/bin/varnishtest/vtc_syslog.c
@@ -246,7 +246,7 @@ syslog_new(const char *name, struct vtclog *vl)
 	ALLOC_OBJ(s, SYSLOG_SRV_MAGIC);
 	AN(s);
 	REPLACE(s->name, name);
-	s->vl = vtc_logopen(s->name);
+	s->vl = vtc_logopen("%s", s->name);
 	AN(s->vl);
 
 	bprintf(s->bind, "%s", "127.0.0.1 0");
@@ -255,7 +255,7 @@ syslog_new(const char *name, struct vtclog *vl)
 	s->lvl = -1;
 	s->timeout = vtc_maxdur * .5;		// XXX
 
-	vl = vtc_logopen(s->name);
+	vl = vtc_logopen("%s", s->name);
 	AN(vl);
 
 	s->rxbuf_sz = s->rxbuf_left = 2048*1024;
diff --git a/bin/varnishtest/vtc_varnish.c b/bin/varnishtest/vtc_varnish.c
index 78705f897..8bb701baa 100644
--- a/bin/varnishtest/vtc_varnish.c
+++ b/bin/varnishtest/vtc_varnish.c
@@ -320,7 +320,7 @@ varnish_new(const char *name)
 
 	REPLACE(v->jail, "");
 
-	v->vl = vtc_logopen(name);
+	v->vl = vtc_logopen("%s", name);
 	AN(v->vl);
 
 	vsb = macro_expandf(v->vl, "${tmpdir}/%s", name);


More information about the varnish-commit mailing list