From: phk Date: Thu, 9 Oct 2008 11:39:24 +0000 (+0000) Subject: Overhaul the varnishtest program to fix a race condition which might X-Git-Url: https://err.no/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e980272498d67ea4d492a3379823c19906dd1ce7;p=varnish 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: svn+ssh://projects.linpro.no/svn/varnish/trunk@3272 d4fa192b-c00b-0410-8231-f00ffab90ce4 --- diff --git a/varnish-cache/bin/varnishtest/flint.lnt b/varnish-cache/bin/varnishtest/flint.lnt index babc1f30..ebd5d9a5 100644 --- a/varnish-cache/bin/varnishtest/flint.lnt +++ b/varnish-cache/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 diff --git a/varnish-cache/bin/varnishtest/tests/a00008.vtc b/varnish-cache/bin/varnishtest/tests/a00008.vtc index 84f9094e..51a7eff7 100644 --- a/varnish-cache/bin/varnishtest/tests/a00008.vtc +++ b/varnish-cache/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 diff --git a/varnish-cache/bin/varnishtest/vtc.c b/varnish-cache/bin/varnishtest/vtc.c index 6719a303..9270a4c6 100644 --- a/varnish-cache/bin/varnishtest/vtc.c +++ b/varnish-cache/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); diff --git a/varnish-cache/bin/varnishtest/vtc.h b/varnish-cache/bin/varnishtest/vtc.h index 458b040d..5ee4156f 100644 --- a/varnish-cache/bin/varnishtest/vtc.h +++ b/varnish-cache/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); diff --git a/varnish-cache/bin/varnishtest/vtc_client.c b/varnish-cache/bin/varnishtest/vtc_client.c index cf9c3e43..3f93984a 100644 --- a/varnish-cache/bin/varnishtest/vtc_client.c +++ b/varnish-cache/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); } } diff --git a/varnish-cache/bin/varnishtest/vtc_http.c b/varnish-cache/bin/varnishtest/vtc_http.c index e77069a9..e84b579f 100644 --- a/varnish-cache/bin/varnishtest/vtc_http.c +++ b/varnish-cache/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); diff --git a/varnish-cache/bin/varnishtest/vtc_log.c b/varnish-cache/bin/varnishtest/vtc_log.c index 1401aacf..506e6d88 100644 --- a/varnish-cache/bin/varnishtest/vtc_log.c +++ b/varnish-cache/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; diff --git a/varnish-cache/bin/varnishtest/vtc_sema.c b/varnish-cache/bin/varnishtest/vtc_sema.c index 1c6da2ee..959492d1 100644 --- a/varnish-cache/bin/varnishtest/vtc_sema.c +++ b/varnish-cache/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); } } diff --git a/varnish-cache/bin/varnishtest/vtc_server.c b/varnish-cache/bin/varnishtest/vtc_server.c index c2177223..e01a04ba 100644 --- a/varnish-cache/bin/varnishtest/vtc_server.c +++ b/varnish-cache/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; diff --git a/varnish-cache/bin/varnishtest/vtc_varnish.c b/varnish-cache/bin/varnishtest/vtc_varnish.c index d2266146..51ffa633 100644 --- a/varnish-cache/bin/varnishtest/vtc_varnish.c +++ b/varnish-cache/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; }