Rework the output of messages and add -q and -v options.

This allows us to use buffered approaches later, if the file descritor
lock stats to interfere with our concurrency.



git-svn-id: http://www.varnish-cache.org/svn/trunk/varnish-cache@2736 d4fa192b-c00b-0410-8231-f00ffab90ce4

bin/varnishtest/Makefile.am

@@ -8,6 +8,7 @@ varnishtest_SOURCES = \
 		vtc.c \
 		vtc_client.c \
 		vtc_http.c \
+		vtc_log.c \
 		vtc_server.c \
 		vtc_stats.c \
 		vtc_varnish.c

bin/varnishtest/vtc.c

@@ -42,47 +42,6 @@
 #define		MAX_FILESIZE		(1024 * 1024)
 #define		MAX_TOKENS		20
 
-/**********************************************************************
- * Dump a string
- */
-void
-vct_dump(const char *ident, const char *pfx, const char *str)
-{
-	int nl = 1;
-	struct vsb *vsb;
-
-	if (pfx == NULL)
-		pfx = "";
-	vsb = vsb_newauto();
-	if (str == NULL) 
-		vsb_printf(vsb, "#### %-4s %s(null)\n", ident, pfx);
-	else
-		for(; *str; str++) {
-			if (nl) {
-				vsb_printf(vsb, "#### %-4s %s| ", ident, pfx);
-				nl = 0;
-			}
-			if (*str == '\r')
-				vsb_printf(vsb, "\\r");
-			else if (*str == '\t')
-				vsb_printf(vsb, "\\t");
-			else if (*str == '\n') {
-				vsb_printf(vsb, "\\n\n");
-				nl = 1;
-			} else if (*str < 0x20 || *str > 0x7e)
-				vsb_printf(vsb, "\\x%02x", *str);
-			else
-				vsb_printf(vsb, "%c", *str);
-		}
-	if (!nl)
-		vsb_printf(vsb, "\n");
-	vsb_finish(vsb);
-	AZ(vsb_overflowed(vsb));
-	(void)fputs(vsb_data(vsb), stdout);
-	vsb_delete(vsb);
-}
-
-
 /**********************************************************************
  * Read a file into memory
  */
@@ -264,9 +223,9 @@ cmd_delay(char **av, void *priv)
 	AZ(av[2]);
 	f = strtod(av[1], NULL);
 	if (f > 100.) {
-		sleep((int)f);
+		(void)sleep((int)f);
 	} else {
-		usleep((int)(f * 1e6));
+		(void)usleep((int)(f * 1e6));
 	}
 }
 
@@ -323,8 +282,14 @@ main(int argc, char **argv)
 
 	setbuf(stdout, NULL);
 	setbuf(stderr, NULL);
-	while ((ch = getopt(argc, argv, "")) != -1) {
+	while ((ch = getopt(argc, argv, "qv")) != -1) {
 		switch (ch) {
+		case 'q':
+			vtc_verbosity--;
+			break;
+		case 'v':
+			vtc_verbosity++;
+			break;
 		case '?':
 		default:
 			errx(1, "Usage");

bin/varnishtest/vtc.h

@@ -29,6 +29,7 @@
 typedef void cmd_f(char **av, void *priv);
 
 struct vsb;
+struct vtclog;
 
 struct cmds {
 	const char	*name;
@@ -37,17 +38,18 @@ struct cmds {
 
 void parse_string(char *buf, const struct cmds *cmd, void *priv);
 
-void cmd_dump(char **av, void *priv);
-void cmd_delay(char **av, void *priv);
+cmd_f cmd_dump;
+cmd_f cmd_delay;
+cmd_f cmd_server;
+cmd_f cmd_client;
+cmd_f cmd_stats;
+cmd_f cmd_varnish;
 
-void cmd_server(char **av, void *priv);
-void cmd_client(char **av, void *priv);
-void cmd_vcl(char **av, void *priv);
-void cmd_stats(char **av, void *priv);
-void cmd_varnish(char **av, void *priv);
-
-void http_process(const char *ident, const char *spec, int sock, int client);
-
-void vct_dump(const char *ident, const char *pfx, const char *str);
+void http_process(struct vtclog *vl, const char *spec, int sock, int client);
 
 void cmd_server_genvcl(struct vsb *vsb);
+
+extern int vtc_verbosity;
+struct vtclog *vtc_logopen(const char *id);
+void vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...);
+void vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str);

bin/varnishtest/vtc_client.c

@@ -46,6 +46,7 @@ struct client {
 	unsigned		magic;
 #define CLIENT_MAGIC		0x6242397c
 	char			*name;
+	struct vtclog		*vl;
 	VTAILQ_ENTRY(client)	list;
 
 	char			*spec;
@@ -66,20 +67,22 @@ static void *
 client_thread(void *priv)
 {
 	struct client *c;
+	struct vtclog *vl;
 	int fd = -1;
 
 	CAST_OBJ_NOTNULL(c, priv, CLIENT_MAGIC);
 	AN(c->connect);
 
-	printf("##   %-4s started\n", c->name);
-	printf("###  %-4s connect to %s\n", c->name, c->connect);
+	vl = vtc_logopen(c->name);
+
+	vtc_log(vl, 2, "Started");
+	vtc_log(vl, 3, "Connect to %s", c->connect);
 	fd = VSS_open(c->connect);
 	assert(fd >= 0);
-	printf("###  %-4s connected to %s fd is %d\n",
-	    c->name, c->connect, fd);
-	http_process(c->name, c->spec, fd, 1);
+	vtc_log(vl, 3, "Connected to %s fd is %d", c->connect, fd);
+	http_process(vl, c->spec, fd, 1);
 	AZ(close(fd));
-	printf("##   %-4s ending\n", c->name);
+	vtc_log(vl, 2, "Ending");
 
 	return (NULL);
 }
@@ -93,14 +96,16 @@ client_new(char *name)
 {
 	struct client *c;
 
-	if (*name != 'c') {
-		fprintf(stderr, "---- %-4s Client name must start with 'c'\n",
-		    name);
-		exit (1);
-	}
 	ALLOC_OBJ(c, CLIENT_MAGIC);
 	AN(c);
 	c->name = name;
+	c->vl = vtc_logopen(name);
+	AN(c->vl);
+	if (*name != 'c') {
+		vtc_log(c->vl, 0, "Client name must start with 'c'");
+		exit (1);
+	}
+
 	c->connect = ":9081";
 	VTAILQ_INSERT_TAIL(&clients, c, list);
 	return (c);
@@ -115,7 +120,7 @@ client_start(struct client *c)
 {
 
 	CHECK_OBJ_NOTNULL(c, CLIENT_MAGIC);
-	printf("##   %-4s Starting client\n", c->name);
+	vtc_log(c->vl, 2, "Starting client");
 	AZ(pthread_create(&c->tp, NULL, client_thread, c));
 }
 
@@ -129,11 +134,10 @@ client_wait(struct client *c)
 	void *res;
 
 	CHECK_OBJ_NOTNULL(c, CLIENT_MAGIC);
-	printf("##   %-4s Waiting for client\n", c->name);
+	vtc_log(c->vl, 2, "Waiting for client");
 	AZ(pthread_join(c->tp, &res));
 	if (res != NULL) {
-		fprintf(stderr, "Server %s returned \"%s\"\n",
-		    c->name, (char *)res);
+		vtc_log(c->vl, 0, "Client returned \"%s\"", (char *)res);
 		exit (1);
 	}
 	c->tp = NULL;
@@ -207,7 +211,7 @@ cmd_client(char **av, void *priv)
 			c->spec = *av;
 			continue;
 		}
-		fprintf(stderr, "Unknown client argument: %s\n", *av);
+		vtc_log(c->vl, 0, "Unknown client argument: %s", *av);
 		exit (1);
 	}
 }

bin/varnishtest/vtc_http.c

@@ -49,7 +49,7 @@ struct http {
 	int			fd;
 	int			client;
 	int			timeout;
-	const char		*ident;
+	struct vtclog		*vl;
 
 	int			nrxbuf;
 	char			*rxbuf;
@@ -121,19 +121,16 @@ cmd_http_expect(char **av, void *priv)
 	rhs = cmd_var_resolve(hp, av[2]);
 	if (!strcmp(cmp, "==")) {
 		if (strcmp(lhs, rhs)) {
-			fprintf(stderr, 
-			    "---- %-4s EXPECT %s (%s) %s %s (%s) failed\n",
-			    hp->ident, av[0], lhs, av[1], av[2], rhs);
+			vtc_log(hp->vl, 0, "EXPECT %s (%s) %s %s (%s) failed",
+			    av[0], lhs, av[1], av[2], rhs);
 			exit (1);
 		} else {
-			printf(
-			    "#### %-4s EXPECT %s (%s) %s %s (%s) match\n",
-			    hp->ident, av[0], lhs, av[1], av[2], rhs);
+			vtc_log(hp->vl, 4, "EXPECT %s (%s) %s %s (%s) match",
+			    av[0], lhs, av[1], av[2], rhs);
 		}
 	} else {
-		fprintf(stderr, 
-		    "---- %-4s EXPECT %s (%s) %s %s (%s) not implemented\n",
-		    hp->ident, av[0], lhs, av[1], av[2], rhs);
+		vtc_log(hp->vl, 0, "EXPECT %s (%s) %s %s (%s) not implemented",
+		    av[0], lhs, av[1], av[2], rhs);
 		exit (1);
 	}
 }
@@ -212,7 +209,7 @@ http_splitheader(struct http *hp, int req)
 
 	for (n = 0; n < 3 || hh[n] != NULL; n++) {
 		sprintf(buf, "http[%2d] ", n);
-		vct_dump(hp->ident, buf, hh[n]);
+		vtc_dump(hp->vl, 4, buf, hh[n]);
 	}
 }
 
@@ -257,7 +254,7 @@ http_rxhdr(struct http *hp)
 		if (i == 2)
 			break;
 	}
-	vct_dump(hp->ident, NULL, hp->rxbuf);
+	vtc_dump(hp->vl, 4, NULL, hp->rxbuf);
 }
 
 
@@ -279,7 +276,7 @@ cmd_http_rxresp(char **av, void *priv)
 		fprintf(stderr, "Unknown http rxresp spec: %s\n", *av);
 		exit (1);
 	}
-	printf("###  %-4s rxresp\n", hp->ident);
+	vtc_log(hp->vl, 3, "rxresp");
 	http_rxhdr(hp);
 	http_splitheader(hp, 0);
 }
@@ -357,7 +354,7 @@ cmd_http_txresp(char **av, void *priv)
 	}
 	vsb_finish(vsb);
 	AZ(vsb_overflowed(vsb));
-	vct_dump(hp->ident, NULL, vsb_data(vsb));
+	vtc_dump(hp->vl, 4, NULL, vsb_data(vsb));
 	l = write(hp->fd, vsb_data(vsb), vsb_len(vsb));
 	assert(l == vsb_len(vsb));
 	vsb_delete(vsb);
@@ -381,7 +378,7 @@ cmd_http_rxreq(char **av, void *priv)
 		fprintf(stderr, "Unknown http rxreq spec: %s\n", *av);
 		exit (1);
 	}
-	printf("###  %-4s rxreq\n", hp->ident);
+	vtc_log(hp->vl, 3, "rxreq");
 	http_rxhdr(hp);
 	http_splitheader(hp, 1);
 }
@@ -449,7 +446,7 @@ cmd_http_txreq(char **av, void *priv)
 	vsb_cat(vsb, nl);
 	vsb_finish(vsb);
 	AZ(vsb_overflowed(vsb));
-	vct_dump(hp->ident, NULL, vsb_data(vsb));
+	vtc_dump(hp->vl, 4, NULL, vsb_data(vsb));
 	l = write(hp->fd, vsb_data(vsb), vsb_len(vsb));
 	assert(l == vsb_len(vsb));
 	vsb_delete(vsb);
@@ -470,7 +467,7 @@ static struct cmds http_cmds[] = {
 };
 
 void
-http_process(const char *ident, const char *spec, int sock, int client)
+http_process(struct vtclog *vl, const char *spec, int sock, int client)
 {
 	struct http *hp;
 	char *s, *q;
@@ -478,7 +475,7 @@ http_process(const char *ident, const char *spec, int sock, int client)
 	ALLOC_OBJ(hp, HTTP_MAGIC);
 	AN(hp);
 	hp->fd = sock;
-	hp->ident = ident;
+	hp->vl = vl;
 	hp->client = client;
 	hp->timeout = 1000;
 	hp->nrxbuf = 8192;

bin/varnishtest/vtc_server.c

@@ -48,6 +48,7 @@ struct server {
 	unsigned		magic;
 #define SERVER_MAGIC		0x55286619
 	char			*name;
+	struct vtclog		*vl;
 	VTAILQ_ENTRY(server)	list;
 
 	unsigned		repeat;
@@ -74,6 +75,7 @@ static void *
 server_thread(void *priv)
 {
 	struct server *s;
+	struct vtclog *vl;
 	int i, fd;
 	struct sockaddr_storage addr_s;
 	struct sockaddr *addr;
@@ -83,19 +85,20 @@ server_thread(void *priv)
 	CAST_OBJ_NOTNULL(s, priv, SERVER_MAGIC);
 	assert(s->sock >= 0);
 
-	printf("##   %-4s started on %s\n", s->name, s->listen);
+	vl = vtc_logopen(s->name);
+
+	vtc_log(vl, 2, "Started on %s", s->listen);
 	for (i = 0; i < s->repeat; i++) {
 		if (s->repeat > 1)
-			printf("###  %-4s iteration %d\n", s->name, i);
+			vtc_log(vl, 3, "Iteration %d", i);
 		addr = (void*)&addr_s;
 		l = sizeof addr_s;
 		fd = accept(s->sock, addr, &l);
-		printf("#### %-4s Accepted socket %d\n", s->name, fd);
-		http_process(s->name, s->spec, fd, 0);
+		vtc_log(vl, 3, "Accepted socket fd is %d", fd);
+		http_process(vl, s->spec, fd, 0);
 		AZ(close(fd));
 	}
-	printf("##   %-4s ending\n", s->name);
-
+	vtc_log(vl, 2, "Ending");
 	return (NULL);
 }
 
@@ -108,14 +111,15 @@ server_new(char *name)
 {
 	struct server *s;
 
-	if (*name != 's') {
-		fprintf(stderr, "---- %-4s Server name must start with 's'\n",
-		    name);
-		exit (1);
-	}
 	ALLOC_OBJ(s, SERVER_MAGIC);
 	AN(s);
 	s->name = name;
+	s->vl = vtc_logopen(name);
+	AN(s->vl);
+	if (*name != 's') {
+		vtc_log(s->vl, 0, "Server name must start with 's'");
+		exit (1);
+	}
 	s->listen = ":9080";
 	AZ(VSS_parse(s->listen, &s->addr, &s->port));
 	s->repeat = 1;
@@ -135,21 +139,21 @@ server_start(struct server *s)
 	int naddr;
 
 	CHECK_OBJ_NOTNULL(s, SERVER_MAGIC);
-	printf("##   %-4s Starting server\n", s->name);
+	vtc_log(s->vl, 2, "Starting server");
 	if (s->sock < 0) {
 		naddr = VSS_resolve(s->addr, s->port, &s->vss_addr);
 		if (naddr != 1) {
-			fprintf(stderr,
-			    "Server %s listen address not unique\n"
-			    "   \"%s\" resolves to (%d) sockets\n",
-			    s->name, s->listen, naddr);
+			vtc_log(s->vl, 0,
+			    "Server s listen address not unique"
+			    " \"%s\" resolves to (%d) sockets",
+			    s->listen, naddr);
 			exit (1);
 		}
 		s->sock = VSS_listen(s->vss_addr[0], s->depth);
 		assert(s->sock >= 0);
 	}
-	printf("###  %-4s listen on %s (fd %d)\n",
-	    s->name, s->listen, s->sock);
+	vtc_log(s->vl, 3, "listen on %s (fd %d)",
+	    s->listen, s->sock);
 	AZ(pthread_create(&s->tp, NULL, server_thread, s));
 }
 
@@ -163,11 +167,11 @@ server_wait(struct server *s)
 	void *res;
 
 	CHECK_OBJ_NOTNULL(s, SERVER_MAGIC);
-	printf("##   %-4s Waiting for server\n", s->name);
+	vtc_log(s->vl, 2, "Waiting for server");
 	AZ(pthread_join(s->tp, &res));
 	if (res != NULL) {
-		fprintf(stderr, "Server %s returned \"%s\"\n",
-		    s->name, (char *)res);
+		vtc_log(s->vl, 0, "Server returned \"%s\"",
+		    (char *)res);
 		exit (1);
 	}
 	s->tp = NULL;
@@ -251,7 +255,7 @@ cmd_server(char **av, void *priv)
 			s->spec = *av;
 			continue;
 		}
-		fprintf(stderr, "Unknown server argument: %s\n", *av);
+		vtc_log(s->vl, 0, "Unknown server argument: %s", *av);
 		exit (1);
 	}
 }

bin/varnishtest/vtc_varnish.c

@@ -56,6 +56,7 @@ struct varnish {
 	unsigned		magic;
 #define VARNISH_MAGIC		0x208cd8e3
 	char			*name;
+	struct vtclog		*vl;
 	VTAILQ_ENTRY(varnish)	list;
 
 	const char		*args;
@@ -66,11 +67,6 @@ struct varnish {
 
 	pthread_t		tp;
 
-	char			*addr;
-	char			*port;
-	int			naddr;
-	struct vss_addr		**vss_addr;
-
 	int			cli_fd;
 	int			vcl_nbr;
 };
@@ -82,27 +78,27 @@ static VTAILQ_HEAD(, varnish)	varnishes =
  * Ask a question over CLI
  */
 
-static unsigned
-varnish_ask_cli(struct varnish *v, const char *cmd, char **repl)
+static enum cli_status_e
+varnish_ask_cli(const struct varnish *v, const char *cmd, char **repl)
 {
 	int i;
 	unsigned retval;
 	char *r;
 
-	vct_dump(v->name, "CLI TX", cmd);
+	vtc_dump(v->vl, 4, "CLI TX", cmd);
 	i = write(v->cli_fd, cmd, strlen(cmd));
 	assert(i == strlen(cmd));
 	i = write(v->cli_fd, "\n", 1);
 	assert(i == 1);
 	i = cli_readres(v->cli_fd, &retval, &r, 1000);
 	assert(i == 0);
-	printf("###  %-4s CLI %u <%s>\n", v->name, retval, cmd);
-	vct_dump(v->name, "CLI RX", r);
+	vtc_log(v->vl, 3, "CLI %u <%s>", retval, cmd);
+	vtc_dump(v->vl, 4, "CLI RX", r);
 	if (repl != NULL)
 		*repl = r;
 	else
 		free(r);
-	return (retval);
+	return ((enum cli_status_e)retval);
 }
 
 static void
@@ -136,14 +132,16 @@ varnish_new(char *name)
 {
 	struct varnish *v;
 
-	if (*name != 'v') {
-		fprintf(stderr,
-		    "---- %-4s Varnish name must start with 'v'\n", name);
-		exit (1);
-	}
 	ALLOC_OBJ(v, VARNISH_MAGIC);
 	AN(v);
 	v->name = name;
+	v->vl = vtc_logopen(name);
+	AN(v->vl);
+	if (*name != 'v') {
+		vtc_log(v->vl, 0, "Varnish name must start with 'v'");
+		exit (1);
+	}
+
 	v->args = "";
 	v->telnet = ":9001";
 	v->accept = ":9081";
@@ -169,7 +167,7 @@ varnish_thread(void *priv)
 		if (i <= 0)
 			break;
 		buf[i] = '\0';
-		vct_dump(v->name, "debug", buf);
+		vtc_dump(v->vl, 4, "debug", buf);
 	}
 	return (NULL);
 }
@@ -184,7 +182,7 @@ varnish_launch(struct varnish *v)
 	struct vsb *vsb;
 	int i;
 
-	printf("##   %-4s Launch\n", v->name);
+	vtc_log(v->vl, 2, "Launch");
 	vsb = vsb_newauto();
 	AN(vsb);
 	vsb_printf(vsb, "cd ../varnishd &&");
@@ -193,7 +191,7 @@ varnish_launch(struct varnish *v)
 	vsb_printf(vsb, " %s", v->args);
 	vsb_finish(vsb);
 	AZ(vsb_overflowed(vsb));
-	printf("###  %-4s CMD: %s\n", v->name, vsb_data(vsb));
+	vtc_log(v->vl, 3, "CMD: %s", vsb_data(vsb));
 	AZ(pipe(&v->fds[0]));
 	AZ(pipe(&v->fds[2]));
 	v->pid = fork();
@@ -216,19 +214,19 @@ varnish_launch(struct varnish *v)
 	vsb_delete(vsb);
 	AZ(pthread_create(&v->tp, NULL, varnish_thread, v));
 
-	printf("###  %-4s opening CLI connection\n", v->name);
+	vtc_log(v->vl, 3, "opening CLI connection");
 	for (i = 0; i < 10; i++) {
-		usleep(200000);
+		(void)usleep(200000);
 		v->cli_fd = VSS_open(v->telnet);
 		if (v->cli_fd >= 0)
 			break;
 	}
 	if (v->cli_fd < 0) {
-		fprintf(stderr, "---- %-4s FAIL no CLI connection\n", v->name);
-		kill(v->pid, SIGKILL);
+		vtc_log(v->vl, 0, "FAIL no CLI connection");
+		(void)kill(v->pid, SIGKILL);
 		exit (1);
 	}
-	printf("###  %-4s CLI connection fd = %d\n", v->name, v->cli_fd);
+	vtc_log(v->vl, 3, "CLI connection fd = %d", v->cli_fd);
 	assert(v->cli_fd >= 0);
 }
 
@@ -239,11 +237,11 @@ varnish_launch(struct varnish *v)
 static void
 varnish_start(struct varnish *v)
 {
-	unsigned u;
+	enum cli_status_e u;
 
 	if (v->cli_fd < 0)
 		varnish_launch(v);
-	printf("##   %-4s Start\n", v->name);
+	vtc_log(v->vl, 2, "Start");
 	u = varnish_ask_cli(v, "start", NULL);
 	assert(u == CLIS_OK);
 	u = varnish_ask_cli(v, "debug.xid 1000", NULL);
@@ -260,8 +258,8 @@ varnish_stop(struct varnish *v)
 
 	if (v->cli_fd < 0)
 		varnish_launch(v);
-	printf("##   %-4s Stop\n", v->name);
-	varnish_ask_cli(v, "stop", NULL);
+	vtc_log(v->vl, 2, "Stop");
+	(void)varnish_ask_cli(v, "stop", NULL);
 }
 
 /**********************************************************************
@@ -277,7 +275,7 @@ varnish_wait(struct varnish *v)
 	if (v->cli_fd < 0)
 		return;
 	varnish_stop(v);
-	printf("##   %-4s Wait\n", v->name);
+	vtc_log(v->vl, 2, "Wait");
 	AZ(close(v->cli_fd));
 	v->cli_fd = -1;
 
@@ -286,7 +284,7 @@ varnish_wait(struct varnish *v)
 	AZ(pthread_join(v->tp, &p));
 	AZ(close(v->fds[0]));
 	r = wait4(v->pid, &status, 0, NULL);
-	printf("##   %-4s R %d Status: %04x\n", v->name, r, status);
+	vtc_log(v->vl, 2, "R %d Status: %04x", r, status);
 }
 
 /**********************************************************************
@@ -296,12 +294,12 @@ varnish_wait(struct varnish *v)
 static void
 varnish_cli(struct varnish *v, const char *cli)
 {
-	unsigned u;
+	enum cli_status_e u;
 
 	if (v->cli_fd < 0)
 		varnish_launch(v);
 	u = varnish_ask_cli(v, cli, NULL);
-	printf("##   %-4s CLI %03u <%s>\n", v->name, u, cli);
+	vtc_log(v->vl, 2, "CLI %03u <%s>", u, cli);
 }
 
 /**********************************************************************
@@ -309,10 +307,10 @@ varnish_cli(struct varnish *v, const char *cli)
  */
 
 static void
-varnish_vcl(struct varnish *v, char *vcl)
+varnish_vcl(struct varnish *v, const char *vcl)
 {
 	struct vsb *vsb;
-	unsigned u;
+	enum cli_status_e u;
 
 	if (v->cli_fd < 0)
 		varnish_launch(v);
@@ -361,7 +359,7 @@ varnish_vclbackend(struct varnish *v, char *vcl)
 {
 	struct vsb *vsb, *vsb2;
 	char *p;
-	unsigned u;
+	enum cli_status_e u;
 
 	if (v->cli_fd < 0)
 		varnish_launch(v);
@@ -483,7 +481,7 @@ cmd_varnish(char **av, void *priv)
 			varnish_wait(v);
 			continue;
 		}
-		fprintf(stderr, "Unknown varnish argument: %s\n", *av);
+		vtc_log(v->vl, 0, "Unknown varnish argument: %s", *av);
 		exit (1);
 	}
 }