[master] 1ff8836 Make it possible to mark http stuff "non-fatal".

Poul-Henning Kamp phk at varnish-cache.org
Tue Oct 25 11:45:10 CEST 2011


commit 1ff88369bf3690020975f2250ebad4ada39d1e0d
Author: Poul-Henning Kamp <phk at FreeBSD.org>
Date:   Tue Oct 25 09:33:57 2011 +0000

    Make it possible to mark http stuff "non-fatal".
    
    The thread (s%d/c%d) still dies, but it does not mark this as
    fatal with respect to the test as such.
    
    This is useful where varnishd shuts the connection on a backend
    prematurely, as part of the correct execution of a test.
    
    Fix a undue recursion problem with asserts in the vtc_log code.

diff --git a/bin/varnishtest/vtc.h b/bin/varnishtest/vtc.h
index a1b6cbd..ee5308a 100644
--- a/bin/varnishtest/vtc.h
+++ b/bin/varnishtest/vtc.h
@@ -77,10 +77,10 @@ void cmd_server_genvcl(struct vsb *vsb);
 void vtc_loginit(char *buf, unsigned buflen);
 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,
+void vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...);
+void vtc_dump(struct vtclog *vl, int lvl, const char *pfx,
     const char *str, int len);
-void vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx,
+void vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
     const unsigned char *str, int len);
 
 int exec_file(const char *fn, const char *script, const char *tmpdir,
diff --git a/bin/varnishtest/vtc_http.c b/bin/varnishtest/vtc_http.c
index 698ffb0..69485cc 100644
--- a/bin/varnishtest/vtc_http.c
+++ b/bin/varnishtest/vtc_http.c
@@ -67,6 +67,8 @@ struct http {
 
 	int			gziplevel;
 	int			gzipresidual;
+
+	int			fatal;
 };
 
 #define ONLY_CLIENT(hp, av)						\
@@ -137,7 +139,7 @@ http_write(const struct http *hp, int lvl, const char *pfx)
 	vtc_dump(hp->vl, lvl, pfx, VSB_data(hp->vsb), VSB_len(hp->vsb));
 	l = write(hp->fd, VSB_data(hp->vsb), VSB_len(hp->vsb));
 	if (l != VSB_len(hp->vsb))
-		vtc_log(hp->vl, 0, "Write failed: (%d vs %d) %s",
+		vtc_log(hp->vl, hp->fatal, "Write failed: (%d vs %d) %s",
 		    l, VSB_len(hp->vsb), strerror(errno));
 }
 
@@ -339,10 +341,12 @@ http_rxchar(struct http *hp, int n, int eof)
 		pfd[0].revents = 0;
 		i = poll(pfd, 1, hp->timeout);
 		if (i == 0)
-			vtc_log(hp->vl, 0, "HTTP rx timeout (fd:%d %u ms)",
+			vtc_log(hp->vl, hp->fatal,
+			    "HTTP rx timeout (fd:%d %u ms)",
 			    hp->fd, hp->timeout);
 		if (i < 0)
-			vtc_log(hp->vl, 0, "HTTP rx failed (fd:%d poll: %s)",
+			vtc_log(hp->vl, hp->fatal,
+			    "HTTP rx failed (fd:%d poll: %s)",
 			    hp->fd, strerror(errno));
 		assert(i > 0);
 		assert(hp->prxbuf + n < hp->nrxbuf);
@@ -354,10 +358,12 @@ http_rxchar(struct http *hp, int n, int eof)
 		if (i == 0 && eof)
 			return (i);
 		if (i == 0)
-			vtc_log(hp->vl, 0, "HTTP rx EOF (fd:%d read: %s)",
+			vtc_log(hp->vl, hp->fatal,
+			    "HTTP rx EOF (fd:%d read: %s)",
 			    hp->fd, strerror(errno));
 		if (i < 0)
-			vtc_log(hp->vl, 0, "HTTP rx failed (fd:%d read: %s)",
+			vtc_log(hp->vl, hp->fatal,
+			    "HTTP rx failed (fd:%d read: %s)",
 			    hp->fd, strerror(errno));
 		hp->prxbuf += i;
 		hp->rxbuf[hp->prxbuf] = '\0';
@@ -381,7 +387,7 @@ http_rxchunk(struct http *hp)
 	bprintf(hp->chunklen, "%d", i);
 	if ((q == hp->rxbuf + l) ||
 		(*q != '\0' && !vct_islws(*q))) {
-		vtc_log(hp->vl, 0, "chunked fail %02x @ %d",
+		vtc_log(hp->vl, hp->fatal, "chunked fail %02x @ %d",
 		    *q, q - (hp->rxbuf + l));
 	}
 	assert(q != hp->rxbuf + l);
@@ -395,11 +401,11 @@ http_rxchunk(struct http *hp)
 	l = hp->prxbuf;
 	(void)http_rxchar(hp, 2, 0);
 	if(!vct_iscrlf(hp->rxbuf[l]))
-		vtc_log(hp->vl, 0,
+		vtc_log(hp->vl, hp->fatal,
 		    "Wrong chunk tail[0] = %02x",
 		    hp->rxbuf[l] & 0xff);
 	if(!vct_iscrlf(hp->rxbuf[l + 1]))
-		vtc_log(hp->vl, 0,
+		vtc_log(hp->vl, hp->fatal,
 		    "Wrong chunk tail[1] = %02x",
 		    hp->rxbuf[l + 1] & 0xff);
 	hp->prxbuf = l;
@@ -541,7 +547,8 @@ cmd_http_gunzip_body(CMD_ARGS)
 	memset(&vz, 0, sizeof vz);
 
 	if (hp->body[0] != (char)0x1f || hp->body[1] != (char)0x8b)
-		vtc_log(hp->vl, 0, "Gunzip error: Body lacks gzip magics");
+		vtc_log(hp->vl, hp->fatal,
+		    "Gunzip error: Body lacks gzip magics");
 	vz.next_in = TRUST_ME(hp->body);
 	vz.avail_in = hp->bodyl;
 
@@ -570,7 +577,8 @@ cmd_http_gunzip_body(CMD_ARGS)
 	    (uintmax_t)vz.stop_bit,
 	    (uintmax_t)vz.stop_bit >> 3, (uintmax_t)vz.stop_bit & 7);
 	if (i != Z_STREAM_END)
-		vtc_log(hp->vl, 0, "Gunzip error = %d (%s) in:%jd out:%jd",
+		vtc_log(hp->vl, hp->fatal,
+		    "Gunzip error = %d (%s) in:%jd out:%jd",
 		    i, vz.msg, (intmax_t)vz.total_in, (intmax_t)vz.total_out);
 	assert(Z_OK == inflateEnd(&vz));
 }
@@ -602,7 +610,8 @@ gzip_body(const struct http *hp, const char *txt, char **body, int *bodylen)
 	assert(Z_STREAM_END == deflate(&vz, Z_FINISH));
 	i = vz.stop_bit & 7;
 	if (hp->gzipresidual >= 0 && hp->gzipresidual != i)
-		vtc_log(hp->vl, 0, "Wrong gzip residual got %d wanted %d",
+		vtc_log(hp->vl, hp->fatal,
+		    "Wrong gzip residual got %d wanted %d",
 		    i, hp->gzipresidual);
 	*bodylen = vz.total_out;
 	vtc_log(hp->vl, 4, "startbit = %ju %ju/%ju",
@@ -894,7 +903,7 @@ cmd_http_send(CMD_ARGS)
 	vtc_dump(hp->vl, 4, "send", av[1], -1);
 	i = write(hp->fd, av[1], strlen(av[1]));
 	if (i != strlen(av[1]))
-		vtc_log(hp->vl, 0, "Write error in http_send(): %s",
+		vtc_log(hp->vl, hp->fatal, "Write error in http_send(): %s",
 		    strerror(errno));
 }
 
@@ -1036,9 +1045,9 @@ cmd_http_expect_close(CMD_ARGS)
 		fds[0].revents = 0;
 		i = poll(fds, 1, 1000);
 		if (i == 0)
-			vtc_log(vl, 0, "Expected close: timeout");
+			vtc_log(vl, hp->fatal, "Expected close: timeout");
 		if (i != 1 || !(fds[0].revents & POLLIN))
-			vtc_log(vl, 0,
+			vtc_log(vl, hp->fatal,
 			    "Expected close: poll = %d, revents = 0x%x",
 			    i, fds[0].revents);
 		i = read(hp->fd, &c, 1);
@@ -1046,7 +1055,7 @@ cmd_http_expect_close(CMD_ARGS)
 			break;
 		if (i == 1 && vct_islws(c))
 			continue;
-		vtc_log(vl, 0,
+		vtc_log(vl, hp->fatal,
 		    "Expecting close: read = %d, c = 0x%02x", i, c);
 	}
 	vtc_log(vl, 4, "fd=%d EOF, as expected", hp->fd);
@@ -1091,7 +1100,7 @@ cmd_http_accept(CMD_ARGS)
 	vtc_log(vl, 4, "Accepting");
 	hp->fd = accept(*hp->sfd, NULL, NULL);
 	if (hp->fd < 0)
-		vtc_log(vl, 0, "Accepted failed: %s", strerror(errno));
+		vtc_log(vl, hp->fatal, "Accepted failed: %s", strerror(errno));
 	vtc_log(vl, 3, "Accepted socket fd is %d", hp->fd);
 }
 
@@ -1120,6 +1129,26 @@ cmd_http_loop(CMD_ARGS)
 }
 
 /**********************************************************************
+ * Control fatality
+ */
+
+static void
+cmd_http_fatal(CMD_ARGS)
+{
+	struct http *hp;
+	CAST_OBJ_NOTNULL(hp, priv, HTTP_MAGIC);
+
+	AZ(av[1]);
+	if (!strcmp(av[0], "fatal"))
+		hp->fatal = 0;
+	else if (!strcmp(av[0], "non-fatal"))
+		hp->fatal = -1;
+	else {
+		vtc_log(vl, 0, "XXX: fatal %s", cmd->name);
+	}
+}
+
+/**********************************************************************
  * Execute HTTP specifications
  */
 
@@ -1146,6 +1175,8 @@ static const struct cmds http_cmds[] = {
 	{ "close",		cmd_http_close },
 	{ "accept",		cmd_http_accept },
 	{ "loop",		cmd_http_loop },
+	{ "fatal",		cmd_http_fatal },
+	{ "non-fatal",		cmd_http_fatal },
 	{ NULL,			NULL }
 };
 
diff --git a/bin/varnishtest/vtc_log.c b/bin/varnishtest/vtc_log.c
index d6d15c1..313d3ab 100644
--- a/bin/varnishtest/vtc_log.c
+++ b/bin/varnishtest/vtc_log.c
@@ -47,6 +47,7 @@ struct vtclog {
 	const char	*id;
 	struct vsb	*vsb;
 	pthread_mutex_t	mtx;
+	int		act;
 };
 
 static pthread_key_t log_key;
@@ -103,10 +104,12 @@ static const char * const lead[] = {
 #define NLEAD (sizeof(lead)/sizeof(lead[0]))
 
 static void
-vtc_log_emit(const struct vtclog *vl, unsigned lvl)
+vtc_log_emit(const struct vtclog *vl, int lvl)
 {
 	int l;
 
+	if (lvl < 0)
+		lvl = 0;
 	if (vtc_stop && lvl == 0)
 		return;
 	l = VSB_len(vl->vsb);
@@ -121,16 +124,18 @@ vtc_log_emit(const struct vtclog *vl, unsigned lvl)
 
 //lint -e{818}
 void
-vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
+vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
 {
 	double tx;
 
 	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
 	tx = VTIM_mono() - t0;
 	AZ(pthread_mutex_lock(&vl->mtx));
+	vl->act = 1;
 	assert(lvl < NLEAD);
 	VSB_clear(vl->vsb);
-	VSB_printf(vl->vsb, "%s %-4s %4.1f ", lead[lvl], vl->id, tx);
+	VSB_printf(vl->vsb, "%s %-4s %4.1f ",
+	    lead[lvl < 0 ? 1: lvl], vl->id, tx);
 	va_list ap;
 	va_start(ap, fmt);
 	(void)VSB_vprintf(vl->vsb, fmt, ap);
@@ -141,12 +146,14 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 	vtc_log_emit(vl, lvl);
 
 	VSB_clear(vl->vsb);
+	vl->act = 0;
 	AZ(pthread_mutex_unlock(&vl->mtx));
-	if (lvl == 0) {
+	if (lvl > 0)
+		return;
+	if (lvl == 0) 
 		vtc_error = 1;
-		if (pthread_self() != vtc_thread)
-			pthread_exit(NULL);
-	}
+	if (pthread_self() != vtc_thread)
+		pthread_exit(NULL);
 }
 
 /**********************************************************************
@@ -155,7 +162,7 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
 
 //lint -e{818}
 void
-vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int len)
+vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
 {
 	int nl = 1;
 	unsigned l;
@@ -164,7 +171,9 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
 	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
 	tx = VTIM_mono() - t0;
 	assert(lvl < NLEAD);
+	assert(lvl >= 0);
 	AZ(pthread_mutex_lock(&vl->mtx));
+	vl->act = 1;
 	VSB_clear(vl->vsb);
 	if (pfx == NULL)
 		pfx = "";
@@ -204,6 +213,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
 	vtc_log_emit(vl, lvl);
 
 	VSB_clear(vl->vsb);
+	vl->act = 0;
 	AZ(pthread_mutex_unlock(&vl->mtx));
 	if (lvl == 0) {
 		vtc_error = 1;
@@ -218,7 +228,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
 
 //lint -e{818}
 void
-vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned char *str, int len)
+vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx, const unsigned char *str, int len)
 {
 	int nl = 1;
 	unsigned l;
@@ -228,7 +238,9 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha
 	tx = VTIM_mono() - t0;
 	assert(len >= 0);
 	assert(lvl < NLEAD);
+	assert(lvl >= 0);
 	AZ(pthread_mutex_lock(&vl->mtx));
+	vl->act = 1;
 	VSB_clear(vl->vsb);
 	if (pfx == NULL)
 		pfx = "";
@@ -260,6 +272,7 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha
 	vtc_log_emit(vl, lvl);
 
 	VSB_clear(vl->vsb);
+	vl->act = 0;
 	AZ(pthread_mutex_unlock(&vl->mtx));
 	if (lvl == 0) {
 		vtc_error = 1;
@@ -279,7 +292,7 @@ vtc_log_VAS_Fail(const char *func, const char *file, int line,
 	(void)err;
 	(void)xxx;
 	vl = pthread_getspecific(log_key);
-	if (vl == NULL) {
+	if (vl == NULL || vl->act) {
 		fprintf(stderr,
 		    "Assert error in %s(), %s line %d:\n"
 		    "  Condition(%s) not true.\n",



More information about the varnish-commit mailing list