Make verbose=0 the default.

At verbose=0, only spit out a single line if a test passes, but dump
the full show if it fails.

Should make "make check" less tedious to read through.

Fix a race situation related to vsb's while shutting down.




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

bin/varnishtest/vtc.c

@@ -336,7 +336,7 @@ cmd_test(CMD_ARGS)
 		return;
 	assert(!strcmp(av[0], "test"));
 
-	printf("#    TEST %s\n", av[1]);
+	vtc_log(vl, 1, "TEST %s", av[1]);
 	AZ(av[2]);
 	vtc_desc = strdup(av[1]);
 }
@@ -460,12 +460,14 @@ static const struct cmds cmds[] = {
 	{ NULL,		NULL }
 };
 
-static void
+static double
 exec_file(const char *fn, struct vtclog *vl)
 {
 	char *buf;
+	double t0;
 	unsigned old_err;
 
+	t0 = TIM_mono();
 	vtc_stop = 0;
 	vtc_file = fn;
 	vtc_desc = NULL;
@@ -480,12 +482,24 @@ exec_file(const char *fn, struct vtclog *vl)
 	vtc_log(vl, 1, "RESETTING after %s", fn);
 	reset_cmds(cmds);
 	vtc_error = old_err;
+
 	if (vtc_error)
 		vtc_log(vl, 1, "TEST %s FAILED", fn);
-	else
+	else {
 		vtc_log(vl, 1, "TEST %s completed", fn);
+		vtc_logreset();
+	}
+
+	t0 = TIM_mono() - t0;
+
+	if (vtc_error && vtc_verbosity == 0)
+		printf("%s", vtc_logfull());
+	else if (vtc_verbosity == 0)
+		printf("#    top  TEST %s passed (%.3fs)\n", fn, t0);
+
 	vtc_file = NULL;
 	free(vtc_desc);
+	return (t0);
 }
 
 /**********************************************************************
@@ -506,7 +520,7 @@ usage(void)
 int
 main(int argc, char * const *argv)
 {
-	int ch, i, ntest = 1;
+	int ch, i, ntest = 1, ncheck = 0;
 	FILE *fok;
 	static struct vtclog	*vl;
 	double tmax, t0, t00;
@@ -515,6 +529,7 @@ main(int argc, char * const *argv)
 
 	setbuf(stdout, NULL);
 	setbuf(stderr, NULL);
+	vtc_loginit();
 	vl = vtc_logopen("top");
 	AN(vl);
 	while ((ch = getopt(argc, argv, "n:qv")) != -1) {
@@ -551,9 +566,8 @@ main(int argc, char * const *argv)
 	t00 = TIM_mono();
 	for (i = 0; i < ntest; i++) {
 		for (ch = 0; ch < argc; ch++) {
-			t0 = TIM_mono();
-			exec_file(argv[ch], vl);
-			t0 = TIM_mono() - t0;
+			t0 = exec_file(argv[ch], vl);
+			ncheck++;
 			if (t0 > tmax) {
 				tmax = t0;
 				nmax = argv[ch];
@@ -576,9 +590,11 @@ main(int argc, char * const *argv)
 		return (2);
 
 	t00 = TIM_mono() - t00;
-	if (tmax > 0 && nmax != NULL)
-		vtc_log(vl, 1, "Slowest test: %s %.3fs", nmax, tmax);
-	vtc_log(vl, 1, "Total duration: %.3fs", t00);
+	if (ncheck > 1) {
+		printf("#    top  Slowest test: %s %.3fs\n", nmax, tmax);
+		printf("#    top  Total tests run:   %d\n", ncheck);
+		printf("#    top  Total duration: %.3fs\n", t00);
+	}
 
 	fok = fopen("_.ok", "w");
 	if (fok != NULL)

bin/varnishtest/vtc.h

@@ -67,6 +67,9 @@ void http_process(struct vtclog *vl, const char *spec, int sock, int sfd);
 
 void cmd_server_genvcl(struct vsb *vsb);
 
+void vtc_loginit(void);
+void vtc_logreset(void);
+const char *vtc_logfull(void);
 struct vtclog *vtc_logopen(const char *id);
 void vtc_logclose(struct vtclog *vl);
 void vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...);

bin/varnishtest/vtc_log.c

@@ -45,15 +45,48 @@ SVNID("$Id$")
 
 #include "vtc.h"
 
-int vtc_verbosity = 3;
+int vtc_verbosity = 0;
+
+static struct vsb	*vtclog_full;
+static pthread_mutex_t	vtclog_mtx;
 
 struct vtclog {
 	unsigned	magic;
 #define VTCLOG_MAGIC	0x82731202
 	const char	*id;
 	struct vsb	*vsb;
+	pthread_mutex_t	mtx;
 };
 
+/**********************************************************************/
+
+void
+vtc_loginit()
+{
+
+	vtclog_full = vsb_newauto();
+	AN(vtclog_full);
+	AZ(pthread_mutex_init(&vtclog_mtx, NULL));
+}
+
+void
+vtc_logreset()
+{
+
+	vsb_clear(vtclog_full);
+}
+
+const char *
+vtc_logfull(void)
+{
+	vsb_finish(vtclog_full);
+	AZ(vsb_overflowed(vtclog_full));
+	return (vsb_data(vtclog_full));
+}
+
+/**********************************************************************/
+
+
 struct vtclog *
 vtc_logopen(const char *id)
 {
@@ -63,6 +96,7 @@ vtc_logopen(const char *id)
 	AN(vl);
 	vl->id = id;
 	vl->vsb = vsb_newauto();
+	AZ(pthread_mutex_init(&vl->mtx, NULL));
 	return (vl);
 }
 
@@ -72,6 +106,7 @@ vtc_logclose(struct vtclog *vl)
 
 	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
 	vsb_delete(vl->vsb);
+	AZ(pthread_mutex_destroy(&vl->mtx));
 	FREE_OBJ(vl);
 }
 
@@ -91,9 +126,8 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 {
 
 	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
+	AZ(pthread_mutex_lock(&vl->mtx));
 	assert(lvl < NLEAD);
-	if (lvl > vtc_verbosity)
-		return;
 	vsb_clear(vl->vsb);
 	vsb_printf(vl->vsb, "%s %-4s ", lead[lvl], vl->id);
 	va_list ap;
@@ -103,11 +137,16 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 	vsb_putc(vl->vsb, '\n');
 	vsb_finish(vl->vsb);
 	AZ(vsb_overflowed(vl->vsb));
-	(void)fputs(vsb_data(vl->vsb), stdout);
+
+	AZ(pthread_mutex_lock(&vtclog_mtx));
+	vsb_cat(vtclog_full, vsb_data(vl->vsb));
+	AZ(pthread_mutex_unlock(&vtclog_mtx));
+
+	if (lvl > 0 && lvl <= vtc_verbosity)
+		(void)fputs(vsb_data(vl->vsb), stdout);
 	vsb_clear(vl->vsb);
+	AZ(pthread_mutex_unlock(&vl->mtx));
 	if (lvl == 0) {
-		printf("---- TEST FILE: %s\n", vtc_file);
-		printf("---- TEST DESCRIPTION: %s\n", vtc_desc);
 		vtc_error = 1;
 		if (pthread_self() != vtc_thread)
 			pthread_exit(NULL);