From: des <des@d4fa192b-c00b-0410-8231-f00ffab90ce4>
Date: Sun, 17 Feb 2008 22:37:41 +0000 (+0000)
Subject: A number of changes made while trying to reproduce #176:
X-Git-Url: https://err.no/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6c827e50945fa7eeb8c0f39261a080123f9adc5d;p=varnish

A number of changes made while trying to reproduce #176:

 - modify thread_log() to take an "errcode" argument (typically errno) so
   we don't have to sprinkle the code with strerror() calls.

 - read_line() and read_block() would sometimes unnecessarily log an error
   for a short read; let the caller decide whether a short read is
   acceptable.

 - reorder the if / else if / else blocks in receive_response() so the
   logic is easier to follow.

 - remove test code which we no longer need.

 - fix some style issues; there are still a couple of long lines, though.


git-svn-id: svn+ssh://projects.linpro.no/svn/varnish/trunk@2501 d4fa192b-c00b-0410-8231-f00ffab90ce4
---

diff --git a/varnish-cache/bin/varnishreplay/varnishreplay.c b/varnish-cache/bin/varnishreplay/varnishreplay.c
index 204709bc..08ca944e 100644
--- a/varnish-cache/bin/varnishreplay/varnishreplay.c
+++ b/varnish-cache/bin/varnishreplay/varnishreplay.c
@@ -117,7 +117,7 @@ mailbox_get(struct mailbox *mbox)
 	if (msg != NULL)
 		VSTAILQ_REMOVE_HEAD(&mbox->messages, list);
 	pthread_mutex_unlock(&mbox->lock);
-	return msg;
+	return (msg);
 }
 
 static void
@@ -141,7 +141,7 @@ struct thread {
 static pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER;
 
 static void
-thread_log(int lvl, const char *fmt, ...)
+thread_log(int lvl, int errcode, const char *fmt, ...)
 {
 	va_list ap;
 
@@ -152,6 +152,9 @@ thread_log(int lvl, const char *fmt, ...)
 	va_start(ap, fmt);
 	vfprintf(stderr, fmt, ap);
 	va_end(ap);
+	if (errcode)
+		fprintf(stderr, ": %s", strerror(errcode));
+	fprintf(stderr, "\n");
 	pthread_mutex_unlock(&log_mutex);
 }
 
@@ -182,11 +185,11 @@ thread_get(int fd, void *(*thread_main)(void *))
 		mailbox_create(&threads[fd]->mbox);
 		if (pthread_create(&threads[fd]->thread_id, NULL,
 		    thread_main, threads[fd]) != 0) {
-			thread_log(0, "thread creation failed\n");
+			thread_log(0, errno, "pthread_create()");
 			mailbox_destroy(&threads[fd]->mbox);
 			freez(threads[fd]);
 		}
-		thread_log(1, "thread %p started\n",
+		thread_log(1, 0, "thread %p started",
 		    (void *)threads[fd]->thread_id);
 	}
 	return (threads[fd]);
@@ -207,7 +210,7 @@ thread_close(int fd)
 		return;
 	mailbox_close(&threads[fd]->mbox);
 	pthread_join(threads[fd]->thread_id, NULL);
-	thread_log(1, "thread %p stopped\n",
+	thread_log(1, 0, "thread %p stopped",
 	    (void *)threads[fd]->thread_id);
 	mailbox_destroy(&threads[fd]->mbox);
 	freez(threads[fd]);
@@ -289,14 +292,14 @@ init_connection(const char *address)
 	int i, n;
 
 	if (VSS_parse(address, &addr, &port) != 0) {
-		thread_log(0, "Invalid address\n");
+		thread_log(0, 0, "Invalid address");
 		exit(2);
 	}
 	n = VSS_resolve(addr, port, &ta);
 	free(addr);
 	free(port);
 	if (n == 0) {
-		thread_log(0, "Could not connect to server\n");
+		thread_log(0, 0, "Could not connect to server");
 		exit(2);
 	}
 	for (i = 1; i < n; ++i) {
@@ -306,7 +309,7 @@ init_connection(const char *address)
 	tap = ta[0];
 	free(ta);
 
-	return tap;
+	return (tap);
 }
 
 /* Read a line from the socket and return the number of bytes read.
@@ -325,25 +328,31 @@ read_line(char **line, int sock)
 	XXXAN(buf);
 	nbuf = 0;
 	while (1) {
-		if ((nbuf + 2) >= lbuf) {
+		if (nbuf + 2 >= lbuf) {
 			lbuf += lbuf;
 			buf = realloc(buf, lbuf);
 			XXXAN(buf);
 		}
 		i = read(sock, buf + nbuf, 1);
-		if (i <= 0) {
-			thread_log(0, "read(): %s\n", strerror(errno));
+		if (i < 0) {
+			thread_log(0, errno, "read(%d, %p, %d)",
+			    sock, buf + nbuf, 1);
 			free(buf);
 			return (-1);
 		}
+		if (i == 0) {
+			buf[nbuf] = '\0';
+			break;
+		}
 		nbuf += i;
-		if (nbuf >= 2 && buf[nbuf-2] == '\r' && buf[nbuf-1] == '\n')
+		if (nbuf >= 2 && buf[nbuf-2] == '\r' && buf[nbuf-1] == '\n') {
+			buf[nbuf-2] = '\0';
 			break;
+		}
 
 	}
-	buf[nbuf] = '\0';
 	*line = buf;
-	return nbuf+1;
+	return (nbuf - 2);
 }
 
 /* Read a block of data from the socket, and do nothing with it.
@@ -354,22 +363,25 @@ static int
 read_block(int length, int sock)
 {
 	char *buf;
-	int n, nbuf;
+	int len, n, nbuf;
 
 	buf = malloc(length);
 	nbuf = 0;
 	while (nbuf < length) {
-		n = read(sock, buf + nbuf,
-		    (2048 < length - nbuf ? 2048 : length - nbuf));
-		if (n <= 0) {
-			thread_log(0, "failed reading the block\n");
+		len = 2048 < length - nbuf ? 2048 : length - nbuf;
+		n = read(sock, buf + nbuf, len);
+		if (n < 0) {
+			thread_log(0, errno, "read(%d, %p, %d)",
+			    sock, buf + nbuf, len);
 			nbuf = -1;
 			break;
 		}
+		if (n == 0)
+			break;
 		nbuf += n;
 	}
 	free(buf);
-	return nbuf;
+	return (nbuf);
 }
 
 /* Receive the response after sending a request.
@@ -385,7 +397,7 @@ receive_response(int sock)
 	int close_connection = 0;
 	int req_failed = 1;
 	int n;
-	long block_len;
+	long chunk_len;
 	int status;
 
 	/* Read header */
@@ -394,69 +406,68 @@ receive_response(int sock)
 		if (line_len < 0)
 			return (-1);
 		end = line + line_len;
-
-		if (line_len >= 2 && line[0] == '\r' && line[1] == '\n') {
+		if (line_len == 0) {
 			freez(line);
 			break;
 		}
-
 		if (strncmp(line, "HTTP", 4) == 0) {
 			sscanf(line, "%*s %d %*s\r\n", &status);
 			req_failed = (status != 200);
-		} else if (isprefix(line, "content-length:", end, &next))
-			content_length = strtol(next, &end, 10);
-		else if (isprefix(line, "encoding:", end, &next) ||
-		    isprefix(line, "transfer-encoding:", end, &next))
-			chunked = (strstr(next, "chunked") != NULL);
-		else if (isprefix(line, "connection:", end, &next))
-			close_connection = (strstr(next, "close") != NULL);
-
+		} else if (isprefix(line, "content-length:", end, &next)) {
+			content_length = strtol(next, NULL, 10);
+		} else if (isprefix(line, "transfer-encoding:", end, &next)) {
+			chunked = (strcasecmp(next, "chunked") == 0);
+		} else if (isprefix(line, "connection:", end, &next)) {
+			close_connection = (strcasecmp(next, "close") == 0);
+		}
 		freez(line);
 	}
 
-	thread_log(1, "status: %d\n", status);
+	thread_log(1, 0, "status: %d", status);
 
 
 	/* Read body */
-	if (content_length > 0 && !chunked) {
-		/* Fixed body size, read content_length bytes */
-		thread_log(1, "fixed length\n");
-		thread_log(1, "size of body: %ld\n", content_length);
-		if ((n = read_block(content_length, sock)) < 0)
-			return (1);
-		thread_log(1, "bytes read: %d\n", n);
-	} else if (chunked) {
+	if (chunked) {
 		/* Chunked encoding, read size and bytes until no more */
-		thread_log(1, "chunked encoding\n");
+		thread_log(1, 0, "chunked encoding");
 		for (;;) {
 			if ((line_len = read_line(&line, sock)) < 0)
 				return (-1);
 			end = line + line_len;
-			block_len = strtol(line, &end, 16);
+			/* read_line() guarantees null-termination */
+			chunk_len = strtol(line, NULL, 16);
 			freez(line);
-			if (block_len == 0)
+			if (chunk_len == 0)
 				break;
-			if ((n = read_block(block_len, sock)) < 0)
+			if ((n = read_block(chunk_len, sock)) < 0)
 				return (-1);
-			thread_log(1, "size of body: %d\n", (int)block_len);
-			thread_log(1, "bytes read: %d\n", n);
+			if (n < chunk_len)
+				thread_log(0, 0, "short read: %d/%ld",
+				    n, chunk_len);
+			thread_log(1, 0, "chunk length: %ld", chunk_len);
+			thread_log(1, 0, "bytes read: %d", n);
+			/* trainling CR LF */
 			if ((n = read_line(&line, sock)) < 0)
 				return (-1);
 			freez(line);
 		}
+		/* trailing CR LF */
 		n = read_line(&line, sock);
 		freez(line);
-	} else if ((content_length <= 0 && !chunked) || req_failed) {
-		/* No body --> stop reading. */
-		thread_log(1, "no body\n");
-		return (-1);
+	} else if (content_length > 0) {
+		/* Fixed body size, read content_length bytes */
+		thread_log(1, 0, "fixed length");
+		thread_log(1, 0, "content length: %ld", content_length);
+		if ((n = read_block(content_length, sock)) < 0)
+			return (1);
+		thread_log(1, 0, "bytes read: %d", n);
 	} else {
-		/* Unhandled case. */
-		thread_log(0, "An error occured\n");
+		/* No body --> stop reading. */
+		thread_log(1, 0, "no body");
 		return (-1);
 	}
 
-	return close_connection;
+	return (close_connection);
 }
 
 static void *
@@ -484,7 +495,7 @@ replay_thread(void *arg)
 		ptr = msg->ptr;
 		end = ptr + len;
 
-		thread_log(2, "%s(%s)\n", VSL_tags[tag], msg->ptr);
+		thread_log(2, 0, "%s(%s)", VSL_tags[tag], msg->ptr);
 
 		switch (tag) {
 		case SLT_RxRequest:
@@ -526,7 +537,7 @@ replay_thread(void *arg)
 			bogus = 1;
 
 		if (bogus) {
-			thread_log(1, "bogus\n");
+			thread_log(1, 0, "bogus");
 		} else {
 			/* If the method is supported (GET or HEAD), send the request out
 			 * on the socket. If the socket needs reopening, reopen it first.
@@ -538,7 +549,7 @@ replay_thread(void *arg)
 					sock = VSS_connect(addr_info);
 				reopen = 0;
 
-				thread_log(1, "%s %s %s\n", df_m, df_Uq, df_H);
+				thread_log(1, 0, "%s %s %s", df_m, df_Uq, df_H);
 
 				write(sock, df_m, strlen(df_m));
 				write(sock, " ", 1);
@@ -553,20 +564,18 @@ replay_thread(void *arg)
 
 				write(sock, "Host: ", 6);
 				if (df_Host) {
-					thread_log(1, "Host: %s\n", df_Host);
+					thread_log(1, 0, "Host: %s", df_Host);
 					write(sock, df_Host, strlen(df_Host));
 				}
 				write(sock, "\r\n", 2);
 				if (df_c) {
-					thread_log(1, "Connection: %s\n", df_c);
+					thread_log(1, 0, "Connection: %s", df_c);
 					write(sock, "Connection: ", 12);
 					write(sock, df_c, strlen(df_c));
 					write(sock, "\r\n", 2);
 					if (isequal(df_c, "keep-alive", df_c + strlen(df_c)))
 						reopen = 0;
 				}
-				if (debug)
-					thread_log(0, "\n");
 				write(sock, "\r\n", 2);
 				if (!reopen)
 					reopen = receive_response(sock);
@@ -614,7 +623,7 @@ gen_traffic(void *priv, enum shmlogtag tag, unsigned fd,
 	if (fd == 0 || !(spec & VSL_S_CLIENT))
 		return (0);
 
-	thread_log(2, "%d %s\n", fd, VSL_tags[tag]);
+	thread_log(2, 0, "%d %s", fd, VSL_tags[tag]);
 	thr = thread_get(fd, replay_thread);
 	msg = malloc(sizeof (struct message));
 	msg->tag = tag;
@@ -622,35 +631,7 @@ gen_traffic(void *priv, enum shmlogtag tag, unsigned fd,
 	msg->ptr = strndup(ptr, len);
 	mailbox_put(&thr->mbox, msg);
 
-	return 0;
-}
-
-
-/* This function is for testing only, and only sends
- * the raw data from the file to the address.
- * The receive function is called for each blank line.
- */
-static void
-send_test_request(char *file, const char *address)
-{
-	int fd = open(file, O_RDONLY);
-	char buf[2];
-	char last = ' ';
-	int sock, reopen = 1;
-
-	addr_info = init_connection(address);
-	sock = VSS_connect(addr_info);
-	while (read(fd, buf, 1)) {
-		write(sock, buf, 1);
-		thread_log(0, "%s", buf);
-		if (*buf == '\n' && last == '\n'){
-			thread_log(0, "receive\n");
-			reopen = receive_response(sock);
-		}
-		last = *buf;
-	}
-	close(sock);
-
+	return (0);
 }
 
 /*--------------------------------------------------------------------*/
@@ -659,7 +640,7 @@ static void
 usage(void)
 {
 
-	fprintf(stderr, "usage: varnishreplay -a address:port -r logfile [-D]\n");
+	fprintf(stderr, "usage: varnishreplay [-D] -a address:port -r logfile\n");
 	exit(1);
 }
 
@@ -670,13 +651,11 @@ main(int argc, char *argv[])
 	struct VSL_data *vd;
 	const char *address = NULL;
 
-	char *test_file = NULL;
-
 	vd = VSL_New();
 	debug = 0;
 
 	VSL_Arg(vd, 'c', NULL);
-	while ((c = getopt(argc, argv, "a:Dr:t:")) != -1) {
+	while ((c = getopt(argc, argv, "a:Dr:")) != -1) {
 		switch (c) {
 		case 'a':
 			address = optarg;
@@ -684,13 +663,6 @@ main(int argc, char *argv[])
 		case 'D':
 			++debug;
 			break;
-		case 't':
-			/* This option is for testing only. The test file must contain
-			 * a sequence of valid HTTP-requests that can be sent
-			 * unchanged to the adress given with -a
-			 */
-			test_file = optarg;
-			break;
 		default:
 			if (VSL_Arg(vd, c, optarg) > 0)
 				break;
@@ -698,11 +670,6 @@ main(int argc, char *argv[])
 		}
 	}
 
-	if (test_file != NULL) {
-		send_test_request(test_file, address);
-		exit(0);
-	}
-
 	if (address == NULL) {
 		usage();
 	}