Overhaul the varnishtest program to fix a race condition which might

(or might not) be the root cause of #346:

The delay function would access the toplevel log element from client/server
contexts with no logging.

Fix by passing the log element to the subcommands.

This race would only affect testcases using delay or sema inside client
or server threads.

Revert test a00008.vtc to use only one sema, using two just moved the
race condition.

This also has the side effect of moving "sema" related messages to
the tread that carries out the "sema" operation.

Various other cleanups now that I had my fingers in the code anyway:
memory leaks plugged, stylistic nits etc.



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

bin/varnishtest/flint.lnt

@@ -36,6 +36,9 @@
 // -emacro((826), VTAILQ_PREV) // Suspicious pointer-to-pointer conversion (area too small)
 // -emacro((826), VTAILQ_LAST) // Suspicious pointer-to-pointer conversion (area too small)
 -emacro(506, VTAILQ_FOREACH_SAFE) // constant value boolean
+-emacro(779, REPLACE)		// string constant !=
+-emacro(774, REPLACE)		// if(bool) always true
+-emacro(506, REPLACE)		// const bool
 // 
 -esym(534, sprintf)	// Ignoring return value of function
 // -esym(534, asprintf)	// Ignoring return value of function

bin/varnishtest/tests/a00008.vtc

@@ -27,25 +27,25 @@ client c1 -connect 127.0.0.1:9080 {
 	delay .2
 	txreq
 	rxresp
-	sema r2 sync 4
+	sema r1 sync 4
 } -start
 
 client c2 -connect 127.0.0.1:9081 {
 	delay .6
 	txreq
 	rxresp
-	sema r2 sync 4
+	sema r1 sync 4
 } -start
 
 client c3 -connect 127.0.0.1:9082 {
 	delay .9
 	txreq
 	rxresp
-	sema r2 sync 4
+	sema r1 sync 4
 } -start
 
 # Wait for all servers to have received requests
 sema r1 sync 4
 
 # Wait for all clients to have received responses
-sema r2 sync 4
+sema r1 sync 4

bin/varnishtest/vtc.c

@@ -41,7 +41,8 @@
 #define		MAX_FILESIZE		(1024 * 1024)
 #define		MAX_TOKENS		100
 
-static struct vtclog	*vl;
+const char	*vtc_file;
+char		*vtc_desc;
 
 /**********************************************************************
  * Read a file into memory
@@ -80,7 +81,7 @@ read_file(const char *fn)
  */
 
 void
-parse_string(char *buf, const struct cmds *cmd, void *priv)
+parse_string(char *buf, const struct cmds *cmd, void *priv, struct vtclog *vl)
 {
 	char *token_s[MAX_TOKENS], *token_e[MAX_TOKENS];
 	char *p, *q;
@@ -183,7 +184,7 @@ parse_string(char *buf, const struct cmds *cmd, void *priv)
 		}
 	
 		assert(cp->cmd != NULL);
-		cp->cmd(token_s, priv, cmd);
+		cp->cmd(token_s, priv, cmd, vl);
 	}
 }
 
@@ -196,7 +197,7 @@ reset_cmds(const struct cmds *cmd)
 {
 
 	for (; cmd->name != NULL; cmd++)
-		cmd->cmd(NULL, NULL, NULL);
+		cmd->cmd(NULL, NULL, NULL, NULL);
 }
 
 /**********************************************************************
@@ -209,6 +210,7 @@ cmd_test(CMD_ARGS)
 
 	(void)priv;
 	(void)cmd;
+	(void)vl;
 
 	if (av == NULL)
 		return;
@@ -216,6 +218,7 @@ cmd_test(CMD_ARGS)
 
 	printf("#    TEST %s\n", av[1]);
 	AZ(av[2]);
+	vtc_desc = strdup(av[1]);
 }
 
 /**********************************************************************
@@ -270,6 +273,7 @@ cmd_dump(CMD_ARGS)
 {
 
 	(void)cmd;
+	(void)vl;
 	if (av == NULL)
 		return;
 	printf("cmd_dump(%p)\n", priv);
@@ -293,16 +297,20 @@ static struct cmds cmds[] = {
 };
 
 static void
-exec_file(const char *fn)
+exec_file(const char *fn, struct vtclog *vl)
 {
 	char *buf;
 
-	printf("#    TEST %s starting\n", fn);
+	vtc_file = fn;
+	vtc_desc = NULL;
+	vtc_log(vl, 1, "TEST %s starting", fn);
 	buf = read_file(fn);
-	parse_string(buf, cmds, NULL);
-	printf("#    RESETTING after %s\n", fn);
+	parse_string(buf, cmds, NULL, vl);
+	vtc_log(vl, 1, "RESETTING after %s", fn);
 	reset_cmds(cmds);
-	printf("#    TEST %s completed\n", fn);
+	vtc_log(vl, 1, "TEST %s completed", fn);
+	vtc_file = NULL;
+	free(vtc_desc);
 }
 
 /**********************************************************************
@@ -325,10 +333,11 @@ main(int argc, char * const *argv)
 {
 	int ch;
 	FILE *fok;
+	static struct vtclog	*vl;
 
 	setbuf(stdout, NULL);
 	setbuf(stderr, NULL);
-	vl = vtc_logopen("");
+	vl = vtc_logopen("top");
 	AN(vl);
 	while ((ch = getopt(argc, argv, "qv")) != -1) {
 		switch (ch) {
@@ -350,7 +359,7 @@ main(int argc, char * const *argv)
 
 	init_sema();
 	for (ch = 0; ch < argc; ch++)
-		exec_file(argv[ch]);
+		exec_file(argv[ch], vl);
 	fok = fopen("_.ok", "w");
 	if (fok != NULL)
 		fclose(fok);

bin/varnishtest/vtc.h

@@ -30,7 +30,7 @@ struct vsb;
 struct vtclog;
 struct cmds;
 
-#define CMD_ARGS char * const *av, void *priv, const struct cmds *cmd
+#define CMD_ARGS char * const *av, void *priv, const struct cmds *cmd, struct vtclog *vl
 typedef void cmd_f(CMD_ARGS);
 
 struct cmds {
@@ -38,7 +38,7 @@ struct cmds {
 	cmd_f		*cmd;
 };
 
-void parse_string(char *buf, const struct cmds *cmd, void *priv);
+void parse_string(char *buf, const struct cmds *cmd, void *priv, struct vtclog *vl);
 
 cmd_f cmd_dump;
 cmd_f cmd_delay;
@@ -47,13 +47,17 @@ cmd_f cmd_client;
 cmd_f cmd_varnish;
 cmd_f cmd_sema;
 
+extern const char *vtc_file;
+extern char *vtc_desc;
+extern int vtc_verbosity;
+
 void init_sema(void);
 
 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_logclose(struct vtclog *vl);
 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

@@ -51,7 +51,7 @@ struct client {
 
 	char			*spec;
 	
-	const char		*connect;
+	char			*connect;
 
 	pthread_t		tp;
 };
@@ -98,25 +98,41 @@ client_thread(void *priv)
  */
 
 static struct client *
-client_new(char *name)
+client_new(const char *name)
 {
 	struct client *c;
 
+	AN(name);
 	ALLOC_OBJ(c, CLIENT_MAGIC);
 	AN(c);
-	c->name = name;
+	REPLACE(c->name, name);
 	c->vl = vtc_logopen(name);
 	AN(c->vl);
-	if (*name != 'c') {
+	if (*c->name != 'c')
 		vtc_log(c->vl, 0, "Client name must start with 'c'");
-		exit (1);
-	}
 
-	c->connect = "127.0.0.1:9081";
+	REPLACE(c->connect, "127.0.0.1:9081");
 	VTAILQ_INSERT_TAIL(&clients, c, list);
 	return (c);
 }
 
+/**********************************************************************
+ * Clean up client
+ */
+
+static void
+client_delete(struct client *c)
+{
+
+	CHECK_OBJ_NOTNULL(c, CLIENT_MAGIC);
+	vtc_logclose(c->vl);
+	free(c->spec);
+	free(c->name);
+	free(c->connect);
+	/* XXX: MEMLEAK (?)*/
+	FREE_OBJ(c);
+}
+
 /**********************************************************************
  * Start the client thread
  */
@@ -173,6 +189,7 @@ cmd_client(CMD_ARGS)
 
 	(void)priv;
 	(void)cmd;
+	(void)vl;
 
 	if (av == NULL) {
 		/* Reset and free */
@@ -180,8 +197,7 @@ cmd_client(CMD_ARGS)
 			VTAILQ_REMOVE(&clients, c, list);
 			if (c->tp != 0)
 				client_wait(c);
-			FREE_OBJ(c);
-			/* XXX: MEMLEAK */
+			client_delete(c);
 		}
 		return;
 	}
@@ -198,7 +214,7 @@ cmd_client(CMD_ARGS)
 
 	for (; *av != NULL; av++) {
 		if (!strcmp(*av, "-connect")) {
-			c->connect = av[1];
+			REPLACE(c->connect, av[1]);
 			av++;
 			continue;
 		}
@@ -218,6 +234,6 @@ cmd_client(CMD_ARGS)
 			vtc_log(c->vl, 0, "Unknown client argument: %s", *av);
 			exit (1);
 		}
-		c->spec = *av;
+		REPLACE(c->spec, *av);
 	}
 }

bin/varnishtest/vtc_http.c

@@ -70,7 +70,7 @@ static const char *nl = "\r\n";
  * Generate a synthetic body
  */
 
-static const char *
+static char *
 synth_body(const char *len)
 {
 	int i, j, k, l;
@@ -185,6 +185,7 @@ cmd_http_expect(CMD_ARGS)
 	char *rhs;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	assert(!strcmp(av[0], "expect"));
 	av++;
@@ -419,6 +420,7 @@ cmd_http_rxresp(CMD_ARGS)
 	struct http *hp;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AN(hp->client);
 	assert(!strcmp(av[0], "rxresp"));
@@ -445,9 +447,10 @@ cmd_http_txresp(CMD_ARGS)
 	const char *proto = "HTTP/1.1";
 	const char *status = "200";
 	const char *msg = "Ok";
-	const char *body = NULL;
+	char *body = NULL;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AZ(hp->client);
 	assert(!strcmp(av[0], "txresp"));
@@ -482,7 +485,7 @@ cmd_http_txresp(CMD_ARGS)
 	for(; *av != NULL; av++) {
 		if (!strcmp(*av, "-body")) {
 			AZ(body);
-			body = av[1];
+			REPLACE(body, av[1]);
 			av++;
 		} else if (!strcmp(*av, "-bodylen")) {
 			AZ(body);
@@ -515,6 +518,7 @@ cmd_http_rxreq(CMD_ARGS)
 	struct http *hp;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AZ(hp->client);
 	assert(!strcmp(av[0], "rxreq"));
@@ -544,6 +548,7 @@ cmd_http_txreq(CMD_ARGS)
 	const char *body = NULL;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AN(hp->client);
 	assert(!strcmp(av[0], "txreq"));
@@ -609,6 +614,7 @@ cmd_http_send(CMD_ARGS)
 	int i;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AN(av[1]);
 	AZ(av[2]);
@@ -628,6 +634,7 @@ cmd_http_chunked(CMD_ARGS)
 	struct http *hp;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AN(av[1]);
 	AZ(av[2]);
@@ -646,6 +653,7 @@ cmd_http_timeout(CMD_ARGS)
 	struct http *hp;
 
 	(void)cmd;
+	(void)vl;
 	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
 	AN(av[1]);
 	AZ(av[2]);
@@ -692,7 +700,7 @@ http_process(struct vtclog *vl, const char *spec, int sock, int client)
 	q = strchr(s, '\0');
 	assert(q > s);
 	AN(s);
-	parse_string(s, http_cmds, hp);
+	parse_string(s, http_cmds, hp, vl);
 	vsb_delete(hp->vsb);
 	free(hp->rxbuf);
 	free(hp);

bin/varnishtest/vtc_log.c

@@ -62,6 +62,15 @@ vtc_logopen(const char *id)
 	return (vl);
 }
 
+void
+vtc_logclose(struct vtclog *vl)
+{
+
+	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
+	vsb_delete(vl->vsb);
+	FREE_OBJ(vl);
+}
+
 static const char *lead[] = {
 	"----",
 	"#   ",
@@ -77,6 +86,7 @@ void
 vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 {
 
+	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
 	assert(lvl < NLEAD);
 	if (lvl > vtc_verbosity)
 		return;
@@ -91,8 +101,11 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 	AZ(vsb_overflowed(vl->vsb));
 	(void)fputs(vsb_data(vl->vsb), stdout);
 	vsb_clear(vl->vsb);
-	if (lvl == 0)
+	if (lvl == 0) {
+		printf("---- TEST FILE: %s\n", vtc_file);
+		printf("---- TEST DESCRIPTION: %s\n", vtc_desc);
 		exit (1);
+	}
 }
 
 /**********************************************************************
@@ -105,6 +118,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str)
 {
 	int nl = 1;
 
+	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
 	assert(lvl < NLEAD);
 	if (lvl > vtc_verbosity)
 		return;

bin/varnishtest/vtc_sema.c

@@ -42,7 +42,6 @@ struct sema {
 	unsigned		magic;
 #define SEMA_MAGIC		0x29b64317
 	char			*name;
-	struct vtclog		*vl;
 	VTAILQ_ENTRY(sema)	list;
 	pthread_mutex_t		mtx;
 	pthread_cond_t		cond;
@@ -59,17 +58,15 @@ static VTAILQ_HEAD(, sema)	semas = VTAILQ_HEAD_INITIALIZER(semas);
  */
 
 static struct sema *
-sema_new(char *name)
+sema_new(char *name, struct vtclog *vl)
 {
 	struct sema *r;
 
 	ALLOC_OBJ(r, SEMA_MAGIC);
 	AN(r);
-	r->vl = vtc_logopen(name);
-	AN(r->vl);
 	r->name = name;
 	if (*name != 'r')
-		vtc_log(r->vl, 0, "Sema name must start with 'r'");
+		vtc_log(vl, 0, "Sema name must start with 'r' (%s)", *name);
 
 	AZ(pthread_mutex_init(&r->mtx, NULL));
 	AZ(pthread_cond_init(&r->cond, NULL));
@@ -84,24 +81,31 @@ sema_new(char *name)
  */
 
 static void
-sema_sync(struct sema *r, const char *av)
+sema_sync(struct sema *r, const char *av, struct vtclog *vl)
 {
 	unsigned u;
 
+	CHECK_OBJ_NOTNULL(r, SEMA_MAGIC);
 	u = strtoul(av, NULL, 0);
 
 	AZ(pthread_mutex_lock(&r->mtx));
 	if (r->expected == 0)
 		r->expected = u;
-	assert(r->expected == u);
+	if (r->expected != u)
+		vtc_log(vl, 0,
+		    "Sema(%s) use error: different expectations (%u vs %u)",
+		    r->name, r->expected, u);
 
 	if (++r->waiters == r->expected) {
-		vtc_log(r->vl, 4, "Wake %u", r->expected);
+		vtc_log(vl, 4, "Sema(%s) wake %u", r->name, r->expected);
 		AZ(pthread_cond_broadcast(&r->cond));
 		r->waiters = 0;
 		r->expected = 0;
-	} else 
+	} else {
+		vtc_log(vl, 4, "Sema(%s) wait %u of %u",
+		    r->name, r->waiters, r->expected);
 		AZ(pthread_cond_wait(&r->cond, &r->mtx));
+	}
 	AZ(pthread_mutex_unlock(&r->mtx));
 }
 
@@ -121,9 +125,10 @@ cmd_sema(CMD_ARGS)
 		AZ(pthread_mutex_lock(&sema_mtx));
 		/* Reset and free */
 		VTAILQ_FOREACH_SAFE(r, &semas, list, r2) {
-			VTAILQ_REMOVE(&semas, r, list);
-			FREE_OBJ(r);
-			/* XXX: MEMLEAK */
+			AZ(pthread_mutex_lock(&r->mtx));
+			AZ(r->waiters);
+			AZ(r->expected);
+			AZ(pthread_mutex_unlock(&r->mtx));
 		}
 		AZ(pthread_mutex_unlock(&sema_mtx));
 		return;
@@ -137,7 +142,7 @@ cmd_sema(CMD_ARGS)
 		if (!strcmp(r->name, av[0]))
 			break;
 	if (r == NULL) 
-		r = sema_new(av[0]);
+		r = sema_new(av[0], vl);
 	AZ(pthread_mutex_unlock(&sema_mtx));
 	av++;
 
@@ -145,10 +150,10 @@ cmd_sema(CMD_ARGS)
 		if (!strcmp(*av, "sync")) {
 			av++;
 			AN(*av);
-			sema_sync(r, *av);
+			sema_sync(r, *av, vl);
 			continue;
 		}
-		vtc_log(r->vl, 0, "Unknown sema argument: %s", *av);
+		vtc_log(vl, 0, "Unknown sema argument: %s", *av);
 	}
 }
 

bin/varnishtest/vtc_server.c

@@ -57,7 +57,7 @@ struct server {
 	
 	int			depth;
 	int			sock;
-	const char		*listen;
+	char			*listen;
 	struct vss_addr		**vss_addr;
 	char			*addr;
 	char			*port;
@@ -109,20 +109,20 @@ server_thread(void *priv)
  */
 
 static struct server *
-server_new(char *name)
+server_new(const char *name)
 {
 	struct server *s;
 
+	AN(name);
 	ALLOC_OBJ(s, SERVER_MAGIC);
 	AN(s);
-	s->name = name;
+	REPLACE(s->name, name);
 	s->vl = vtc_logopen(name);
 	AN(s->vl);
-	if (*name != 's') {
+	if (*s->name != 's')
 		vtc_log(s->vl, 0, "Server name must start with 's'");
-		exit (1);
-	}
-	s->listen = "127.0.0.1:9080";
+
+	REPLACE(s->listen, "127.0.0.1:9080");
 	AZ(VSS_parse(s->listen, &s->addr, &s->port));
 	s->repeat = 1;
 	s->depth = 1;
@@ -131,6 +131,22 @@ server_new(char *name)
 	return (s);
 }
 
+/**********************************************************************
+ * Clean up a server
+ */
+
+static void
+server_delete(struct server *s)
+{
+
+	CHECK_OBJ_NOTNULL(s, SERVER_MAGIC);
+	vtc_logclose(s->vl);
+	free(s->listen);
+	free(s->name);
+	/* XXX: MEMLEAK (?) (VSS ??) */
+	FREE_OBJ(s);
+}
+
 /**********************************************************************
  * Start the server thread
  */
@@ -211,6 +227,7 @@ cmd_server(CMD_ARGS)
 
 	(void)priv;
 	(void)cmd;
+	(void)vl;
 
 	if (av == NULL) {
 		/* Reset and free */
@@ -218,8 +235,7 @@ cmd_server(CMD_ARGS)
 			VTAILQ_REMOVE(&servers, s, list);
 			if (s->sock >= 0) 
 				server_wait(s);
-			FREE_OBJ(s);
-			/* XXX: MEMLEAK */
+			server_delete(s);
 		}
 		return;
 	}
@@ -241,7 +257,7 @@ cmd_server(CMD_ARGS)
 			continue;
 		}
 		if (!strcmp(*av, "-listen")) {
-			s->listen = av[1];
+			REPLACE(s->listen, av[1]);
 			AZ(VSS_parse(s->listen, &s->addr, &s->port));
 			av++;
 			continue;

bin/varnishtest/vtc_varnish.c

@@ -131,21 +131,20 @@ varnish_cli_encode(struct vsb *vsb, const char *str)
  */
 
 static struct varnish *
-varnish_new(char *name)
+varnish_new(const char *name)
 {
 	struct varnish *v;
 
+	AN(name);
 	ALLOC_OBJ(v, VARNISH_MAGIC);
 	AN(v);
-	v->name = name;
+	REPLACE(v->name, name);
 	v->vl = vtc_logopen(name);
 	AN(v->vl);
 	v->vl1 = vtc_logopen(name);
 	AN(v->vl1);
-	if (*name != 'v') {
+	if (*v->name != 'v')
 		vtc_log(v->vl, 0, "Varnish name must start with 'v'");
-		exit (1);
-	}
 
 	v->args = "";
 	v->telnet = "127.0.0.1:9001";
@@ -155,6 +154,21 @@ varnish_new(char *name)
 	return (v);
 }
 
+/**********************************************************************
+ * Delete a varnish instance
+ */
+
+static void
+varnish_delete(struct varnish *v)
+{
+
+	CHECK_OBJ_NOTNULL(v, VARNISH_MAGIC);
+	vtc_logclose(v->vl);
+	free(v->name);
+	/* XXX: MEMLEAK */
+	FREE_OBJ(v);
+}
+
 /**********************************************************************
  * Varnish listener
  */
@@ -418,8 +432,8 @@ varnish_vclbackend(struct varnish *v, const char *vcl)
  */
 
 static void
-varnish_expect(struct varnish *v, char * const *av) {
-	uint64_t	val, ref;
+varnish_expect(const struct varnish *v, char * const *av) {
+	uint64_t val, ref;
 	int good;
 	char *p;
 	int i;
@@ -428,6 +442,7 @@ varnish_expect(struct varnish *v, char * const *av) {
 
 	for (i = 0; i < 10; i++, usleep(100000)) {
 
+
 #define MAC_STAT(n, t, f, d) 					\
 		if (!strcmp(av[0], #n)) {			\
 			val = v->stats->n;			\
@@ -435,6 +450,7 @@ varnish_expect(struct varnish *v, char * const *av) {
 #include "stat_field.h"
 #undef MAC_STAT
 		{
+			val = 0;
 			vtc_log(v->vl, 0, "stats field %s unknown", av[0]);
 		}
 
@@ -472,6 +488,7 @@ cmd_varnish(CMD_ARGS)
 
 	(void)priv;
 	(void)cmd;
+	(void)vl;
 
 	if (av == NULL) {
 		/* Reset and free */
@@ -479,8 +496,7 @@ cmd_varnish(CMD_ARGS)
 			if (v->cli_fd >= 0)
 				varnish_wait(v);
 			VTAILQ_REMOVE(&varnishes, v, list);
-			FREE_OBJ(v);
-			/* XXX: MEMLEAK */
+			varnish_delete(v);
 		}
 		return;
 	}