Skip to content

U
unique-xids
Commit e5e7c230 authored by Poul-Henning Kamp's avatar Poul-Henning Kamp Committed by Tollef Fog Heen
Browse files
Options

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.
parent d1bf3bba
Hide whitespace changes
Inline Side-by-side
Showing with 73 additions and 29 deletions
bin/varnishtest/vtc.h
View file @ e5e7c230
...@@ -71,10 +71,10 @@ void cmd_server_genvcl(struct vsb *vsb); ...@@ -71,10 +71,10 @@ void cmd_server_genvcl(struct vsb *vsb);
void vtc_loginit(char *buf, unsigned buflen); void vtc_loginit(char *buf, unsigned buflen);
struct vtclog *vtc_logopen(const char *id); struct vtclog *vtc_logopen(const char *id);
void vtc_logclose(struct vtclog *vl); void vtc_logclose(struct vtclog *vl);
void vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...); void vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...);
void vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, void vtc_dump(struct vtclog *vl, int lvl, const char *pfx,
const char *str, int len); 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); const unsigned char *str, int len);
int exec_file(const char *fn, const char *script, const char *tmpdir, int exec_file(const char *fn, const char *script, const char *tmpdir,
......
bin/varnishtest/vtc_http.c
View file @ e5e7c230
...@@ -73,6 +73,8 @@ struct http { ...@@ -73,6 +73,8 @@ struct http {
int gziplevel; int gziplevel;
int gzipresidual; int gzipresidual;
int fatal;
}; };
#define ONLY_CLIENT(hp, av) \ #define ONLY_CLIENT(hp, av) \
...@@ -143,7 +145,7 @@ http_write(const struct http *hp, int lvl, const char *pfx) ...@@ -143,7 +145,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)); 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)); l = write(hp->fd, VSB_data(hp->vsb), VSB_len(hp->vsb));
if (l != 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)); l, VSB_len(hp->vsb), strerror(errno));
} }
...@@ -345,10 +347,12 @@ http_rxchar(struct http *hp, int n, int eof) ...@@ -345,10 +347,12 @@ http_rxchar(struct http *hp, int n, int eof)
pfd[0].revents = 0; pfd[0].revents = 0;
i = poll(pfd, 1, hp->timeout); i = poll(pfd, 1, hp->timeout);
if (i == 0) 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); hp->fd, hp->timeout);
if (i < 0) 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)); hp->fd, strerror(errno));
assert(i > 0); assert(i > 0);
assert(hp->prxbuf + n < hp->nrxbuf); assert(hp->prxbuf + n < hp->nrxbuf);
...@@ -360,10 +364,12 @@ http_rxchar(struct http *hp, int n, int eof) ...@@ -360,10 +364,12 @@ http_rxchar(struct http *hp, int n, int eof)
if (i == 0 && eof) if (i == 0 && eof)
return (i); return (i);
if (i == 0) 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)); hp->fd, strerror(errno));
if (i < 0) 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->fd, strerror(errno));
hp->prxbuf += i; hp->prxbuf += i;
hp->rxbuf[hp->prxbuf] = '\0'; hp->rxbuf[hp->prxbuf] = '\0';
...@@ -387,7 +393,7 @@ http_rxchunk(struct http *hp) ...@@ -387,7 +393,7 @@ http_rxchunk(struct http *hp)
bprintf(hp->chunklen, "%d", i); bprintf(hp->chunklen, "%d", i);
if ((q == hp->rxbuf + l) || if ((q == hp->rxbuf + l) ||
(*q != '\0' && !vct_islws(*q))) { (*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)); *q, q - (hp->rxbuf + l));
} }
assert(q != hp->rxbuf + l); assert(q != hp->rxbuf + l);
...@@ -401,11 +407,11 @@ http_rxchunk(struct http *hp) ...@@ -401,11 +407,11 @@ http_rxchunk(struct http *hp)
l = hp->prxbuf; l = hp->prxbuf;
(void)http_rxchar(hp, 2, 0); (void)http_rxchar(hp, 2, 0);
if(!vct_iscrlf(hp->rxbuf[l])) if(!vct_iscrlf(hp->rxbuf[l]))
vtc_log(hp->vl, 0, vtc_log(hp->vl, hp->fatal,
"Wrong chunk tail[0] = %02x", "Wrong chunk tail[0] = %02x",
hp->rxbuf[l] & 0xff); hp->rxbuf[l] & 0xff);
if(!vct_iscrlf(hp->rxbuf[l + 1])) if(!vct_iscrlf(hp->rxbuf[l + 1]))
vtc_log(hp->vl, 0, vtc_log(hp->vl, hp->fatal,
"Wrong chunk tail[1] = %02x", "Wrong chunk tail[1] = %02x",
hp->rxbuf[l + 1] & 0xff); hp->rxbuf[l + 1] & 0xff);
hp->prxbuf = l; hp->prxbuf = l;
...@@ -547,7 +553,8 @@ cmd_http_gunzip_body(CMD_ARGS) ...@@ -547,7 +553,8 @@ cmd_http_gunzip_body(CMD_ARGS)
memset(&vz, 0, sizeof vz); memset(&vz, 0, sizeof vz);
if (hp->body[0] != (char)0x1f || hp->body[1] != (char)0x8b) 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.next_in = TRUST_ME(hp->body);
vz.avail_in = hp->bodyl; vz.avail_in = hp->bodyl;
...@@ -576,7 +583,8 @@ cmd_http_gunzip_body(CMD_ARGS) ...@@ -576,7 +583,8 @@ cmd_http_gunzip_body(CMD_ARGS)
(uintmax_t)vz.stop_bit, (uintmax_t)vz.stop_bit,
(uintmax_t)vz.stop_bit >> 3, (uintmax_t)vz.stop_bit & 7); (uintmax_t)vz.stop_bit >> 3, (uintmax_t)vz.stop_bit & 7);
if (i != Z_STREAM_END) 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); i, vz.msg, (intmax_t)vz.total_in, (intmax_t)vz.total_out);
assert(Z_OK == inflateEnd(&vz)); assert(Z_OK == inflateEnd(&vz));
} }
...@@ -608,7 +616,8 @@ gzip_body(const struct http *hp, const char *txt, char **body, int *bodylen) ...@@ -608,7 +616,8 @@ gzip_body(const struct http *hp, const char *txt, char **body, int *bodylen)
assert(Z_STREAM_END == deflate(&vz, Z_FINISH)); assert(Z_STREAM_END == deflate(&vz, Z_FINISH));
i = vz.stop_bit & 7; i = vz.stop_bit & 7;
if (hp->gzipresidual >= 0 && hp->gzipresidual != i) 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); i, hp->gzipresidual);
*bodylen = vz.total_out; *bodylen = vz.total_out;
vtc_log(hp->vl, 4, "startbit = %ju %ju/%ju", vtc_log(hp->vl, 4, "startbit = %ju %ju/%ju",
...@@ -900,7 +909,7 @@ cmd_http_send(CMD_ARGS) ...@@ -900,7 +909,7 @@ cmd_http_send(CMD_ARGS)
vtc_dump(hp->vl, 4, "send", av[1], -1); vtc_dump(hp->vl, 4, "send", av[1], -1);
i = write(hp->fd, av[1], strlen(av[1])); i = write(hp->fd, av[1], strlen(av[1]));
if (i != 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)); strerror(errno));
} }
...@@ -1042,9 +1051,9 @@ cmd_http_expect_close(CMD_ARGS) ...@@ -1042,9 +1051,9 @@ cmd_http_expect_close(CMD_ARGS)
fds[0].revents = 0; fds[0].revents = 0;
i = poll(fds, 1, 1000); i = poll(fds, 1, 1000);
if (i == 0) 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)) if (i != 1 || !(fds[0].revents & POLLIN))
vtc_log(vl, 0, vtc_log(vl, hp->fatal,
"Expected close: poll = %d, revents = 0x%x", "Expected close: poll = %d, revents = 0x%x",
i, fds[0].revents); i, fds[0].revents);
i = read(hp->fd, &c, 1); i = read(hp->fd, &c, 1);
...@@ -1052,7 +1061,7 @@ cmd_http_expect_close(CMD_ARGS) ...@@ -1052,7 +1061,7 @@ cmd_http_expect_close(CMD_ARGS)
break; break;
if (i == 1 && vct_islws(c)) if (i == 1 && vct_islws(c))
continue; continue;
vtc_log(vl, 0, vtc_log(vl, hp->fatal,
"Expecting close: read = %d, c = 0x%02x", i, c); "Expecting close: read = %d, c = 0x%02x", i, c);
} }
vtc_log(vl, 4, "fd=%d EOF, as expected", hp->fd); vtc_log(vl, 4, "fd=%d EOF, as expected", hp->fd);
...@@ -1097,7 +1106,7 @@ cmd_http_accept(CMD_ARGS) ...@@ -1097,7 +1106,7 @@ cmd_http_accept(CMD_ARGS)
vtc_log(vl, 4, "Accepting"); vtc_log(vl, 4, "Accepting");
hp->fd = accept(*hp->sfd, NULL, NULL); hp->fd = accept(*hp->sfd, NULL, NULL);
if (hp->fd < 0) 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); vtc_log(vl, 3, "Accepted socket fd is %d", hp->fd);
} }
...@@ -1125,6 +1134,26 @@ cmd_http_loop(CMD_ARGS) ...@@ -1125,6 +1134,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 * Execute HTTP specifications
*/ */
...@@ -1152,6 +1181,8 @@ static const struct cmds http_cmds[] = { ...@@ -1152,6 +1181,8 @@ static const struct cmds http_cmds[] = {
{ "close", cmd_http_close }, { "close", cmd_http_close },
{ "accept", cmd_http_accept }, { "accept", cmd_http_accept },
{ "loop", cmd_http_loop }, { "loop", cmd_http_loop },
{ "fatal", cmd_http_fatal },
{ "non-fatal", cmd_http_fatal },
{ NULL, NULL } { NULL, NULL }
}; };
......
bin/varnishtest/vtc_log.c
View file @ e5e7c230
...@@ -52,6 +52,7 @@ struct vtclog { ...@@ -52,6 +52,7 @@ struct vtclog {
const char *id; const char *id;
struct vsb *vsb; struct vsb *vsb;
pthread_mutex_t mtx; pthread_mutex_t mtx;
int act;
}; };
static pthread_key_t log_key; static pthread_key_t log_key;
...@@ -108,10 +109,12 @@ static const char * const lead[] = { ...@@ -108,10 +109,12 @@ static const char * const lead[] = {
#define NLEAD (sizeof(lead)/sizeof(lead[0])) #define NLEAD (sizeof(lead)/sizeof(lead[0]))
static void static void
vtc_log_emit(const struct vtclog *vl, unsigned lvl) vtc_log_emit(const struct vtclog *vl, int lvl)
{ {
int l; int l;
if (lvl < 0)
lvl = 0;
if (vtc_stop && lvl == 0) if (vtc_stop && lvl == 0)
return; return;
l = VSB_len(vl->vsb); l = VSB_len(vl->vsb);
...@@ -126,16 +129,18 @@ vtc_log_emit(const struct vtclog *vl, unsigned lvl) ...@@ -126,16 +129,18 @@ vtc_log_emit(const struct vtclog *vl, unsigned lvl)
//lint -e{818} //lint -e{818}
void void
vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...) vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
{ {
double tx; double tx;
CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC); CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
tx = TIM_mono() - t0; tx = TIM_mono() - t0;
AZ(pthread_mutex_lock(&vl->mtx)); AZ(pthread_mutex_lock(&vl->mtx));
vl->act = 1;
assert(lvl < NLEAD); assert(lvl < NLEAD);
VSB_clear(vl->vsb); 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_list ap;
va_start(ap, fmt); va_start(ap, fmt);
(void)VSB_vprintf(vl->vsb, fmt, ap); (void)VSB_vprintf(vl->vsb, fmt, ap);
...@@ -146,12 +151,14 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...) ...@@ -146,12 +151,14 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
vtc_log_emit(vl, lvl); vtc_log_emit(vl, lvl);
VSB_clear(vl->vsb); VSB_clear(vl->vsb);
vl->act = 0;
AZ(pthread_mutex_unlock(&vl->mtx)); AZ(pthread_mutex_unlock(&vl->mtx));
if (lvl == 0) { if (lvl > 0)
return;
if (lvl == 0)
vtc_error = 1; vtc_error = 1;
if (pthread_self() != vtc_thread) if (pthread_self() != vtc_thread)
pthread_exit(NULL); pthread_exit(NULL);
}
} }
/********************************************************************** /**********************************************************************
...@@ -160,7 +167,7 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...) ...@@ -160,7 +167,7 @@ vtc_log(struct vtclog *vl, unsigned lvl, const char *fmt, ...)
//lint -e{818} //lint -e{818}
void 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; int nl = 1;
unsigned l; unsigned l;
...@@ -169,7 +176,9 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int ...@@ -169,7 +176,9 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC); CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
tx = TIM_mono() - t0; tx = TIM_mono() - t0;
assert(lvl < NLEAD); assert(lvl < NLEAD);
assert(lvl >= 0);
AZ(pthread_mutex_lock(&vl->mtx)); AZ(pthread_mutex_lock(&vl->mtx));
vl->act = 1;
VSB_clear(vl->vsb); VSB_clear(vl->vsb);
if (pfx == NULL) if (pfx == NULL)
pfx = ""; pfx = "";
...@@ -209,6 +218,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int ...@@ -209,6 +218,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
vtc_log_emit(vl, lvl); vtc_log_emit(vl, lvl);
VSB_clear(vl->vsb); VSB_clear(vl->vsb);
vl->act = 0;
AZ(pthread_mutex_unlock(&vl->mtx)); AZ(pthread_mutex_unlock(&vl->mtx));
if (lvl == 0) { if (lvl == 0) {
vtc_error = 1; vtc_error = 1;
...@@ -223,7 +233,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int ...@@ -223,7 +233,7 @@ vtc_dump(struct vtclog *vl, unsigned lvl, const char *pfx, const char *str, int
//lint -e{818} //lint -e{818}
void 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; int nl = 1;
unsigned l; unsigned l;
...@@ -233,7 +243,9 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha ...@@ -233,7 +243,9 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha
tx = TIM_mono() - t0; tx = TIM_mono() - t0;
assert(len >= 0); assert(len >= 0);
assert(lvl < NLEAD); assert(lvl < NLEAD);
assert(lvl >= 0);
AZ(pthread_mutex_lock(&vl->mtx)); AZ(pthread_mutex_lock(&vl->mtx));
vl->act = 1;
VSB_clear(vl->vsb); VSB_clear(vl->vsb);
if (pfx == NULL) if (pfx == NULL)
pfx = ""; pfx = "";
...@@ -265,6 +277,7 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha ...@@ -265,6 +277,7 @@ vtc_hexdump(struct vtclog *vl, unsigned lvl, const char *pfx, const unsigned cha
vtc_log_emit(vl, lvl); vtc_log_emit(vl, lvl);
VSB_clear(vl->vsb); VSB_clear(vl->vsb);
vl->act = 0;
AZ(pthread_mutex_unlock(&vl->mtx)); AZ(pthread_mutex_unlock(&vl->mtx));
if (lvl == 0) { if (lvl == 0) {
vtc_error = 1; vtc_error = 1;
...@@ -284,7 +297,7 @@ vtc_log_VAS_Fail(const char *func, const char *file, int line, ...@@ -284,7 +297,7 @@ vtc_log_VAS_Fail(const char *func, const char *file, int line,
(void)err; (void)err;
(void)xxx; (void)xxx;
vl = pthread_getspecific(log_key); vl = pthread_getspecific(log_key);
if (vl == NULL) { if (vl == NULL || vl->act) {
fprintf(stderr, fprintf(stderr,
"Assert error in %s(), %s line %d:\n" "Assert error in %s(), %s line %d:\n"
" Condition(%s) not true.\n", " Condition(%s) not true.\n",
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment