From: phk Date: Fri, 20 Jun 2008 06:56:03 +0000 (+0000) Subject: Rework the output of messages and add -q and -v options. X-Git-Url: https://err.no/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=96d1f8a2e63b89e1429dabf5215728eb65ee97cd;p=varnish 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: svn+ssh://projects.linpro.no/svn/varnish/trunk@2736 d4fa192b-c00b-0410-8231-f00ffab90ce4 --- diff --git a/varnish-cache/bin/varnishtest/Makefile.am b/varnish-cache/bin/varnishtest/Makefile.am index 07e45581..1eb65436 100644 --- a/varnish-cache/bin/varnishtest/Makefile.am +++ b/varnish-cache/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 diff --git a/varnish-cache/bin/varnishtest/vtc.c b/varnish-cache/bin/varnishtest/vtc.c index e6633314..f7cf914e 100644 --- a/varnish-cache/bin/varnishtest/vtc.c +++ b/varnish-cache/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"); diff --git a/varnish-cache/bin/varnishtest/vtc.h b/varnish-cache/bin/varnishtest/vtc.h index cc1e8ff4..75464d3a 100644 --- a/varnish-cache/bin/varnishtest/vtc.h +++ b/varnish-cache/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); diff --git a/varnish-cache/bin/varnishtest/vtc_client.c b/varnish-cache/bin/varnishtest/vtc_client.c index cb33dc7a..d9574606 100644 --- a/varnish-cache/bin/varnishtest/vtc_client.c +++ b/varnish-cache/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); } } diff --git a/varnish-cache/bin/varnishtest/vtc_http.c b/varnish-cache/bin/varnishtest/vtc_http.c index 80e69361..10223b90 100644 --- a/varnish-cache/bin/varnishtest/vtc_http.c +++ b/varnish-cache/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; diff --git a/varnish-cache/bin/varnishtest/vtc_server.c b/varnish-cache/bin/varnishtest/vtc_server.c index 3d9afbfa..d275517e 100644 --- a/varnish-cache/bin/varnishtest/vtc_server.c +++ b/varnish-cache/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); } } diff --git a/varnish-cache/bin/varnishtest/vtc_varnish.c b/varnish-cache/bin/varnishtest/vtc_varnish.c index c717032d..8557c34f 100644 --- a/varnish-cache/bin/varnishtest/vtc_varnish.c +++ b/varnish-cache/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); } }