From: des <des@d4fa192b-c00b-0410-8231-f00ffab90ce4>
Date: Sat, 8 Mar 2008 15:42:23 +0000 (+0000)
Subject: If it looks like a new request starts before a previous request on the same
X-Git-Url: https://err.no/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=265682985f5b34030690fe9dc9eee45a833ddb7f;p=varnish

If it looks like a new request starts before a previous request on the same
fd has finished, flush the previous request with an additional line to note
that the request was interrupted.

This is usually a symptom of the child dying midway through the first
request.


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

diff --git a/varnish-cache/bin/varnishlog/varnishlog.c b/varnish-cache/bin/varnishlog/varnishlog.c
index 3152dd4f..481f2f5e 100644
--- a/varnish-cache/bin/varnishlog/varnishlog.c
+++ b/varnish-cache/bin/varnishlog/varnishlog.c
@@ -82,12 +82,25 @@ name2tag(const char *n)
 
 static struct vsb	*ob[65536];
 static unsigned char	flg[65536];
+static enum shmlogtag   last[65536];
 #define F_INVCL		(1 << 0)
 #define F_MATCH		(1 << 1)
 
 static int		match_tag = -1;
 static regex_t		match_re;
 
+static void
+h_order_finish(int fd)
+{
+
+	vsb_finish(ob[fd]);
+	if (vsb_len(ob[fd]) > 1 &&
+	    (match_tag == -1 || flg[fd] & F_MATCH))
+		printf("%s\n", vsb_data(ob[fd]));
+	flg[fd] &= ~F_MATCH;
+	vsb_clear(ob[fd]);
+}
+
 static void
 clean_order(void)
 {
@@ -108,9 +121,13 @@ clean_order(void)
 static int
 h_order(void *priv, enum shmlogtag tag, unsigned fd, unsigned len, unsigned spec, const char *ptr)
 {
+	char type;
 
 	(void)priv;
 
+	type = (spec & VSL_S_CLIENT) ? 'c' :
+	    (spec & VSL_S_BACKEND) ? 'b' : '-';
+
 	if (!(spec & (VSL_S_CLIENT|VSL_S_BACKEND))) {
 		if (!b_flag && !c_flag)
 			VSL_H_Print(stdout, tag, fd, len, spec, ptr);
@@ -123,6 +140,27 @@ h_order(void *priv, enum shmlogtag tag, unsigned fd, unsigned len, unsigned spec
 	if (tag == match_tag &&
 	    !regexec(&match_re, ptr, 0, NULL, 0))
 		flg[fd] |= F_MATCH;
+
+	if ((tag == SLT_BackendOpen || tag == SLT_SessionOpen ||
+		(tag == SLT_ReqStart &&
+		    last[fd] != SLT_SessionOpen &&
+		    last[fd] != SLT_VCL_acl) ||
+		(tag == SLT_BackendXID &&
+		    last[fd] != SLT_BackendOpen)) &&
+	    vsb_len(ob[fd]) != 0) {
+		/*
+		 * This is the start of a new request, yet we haven't seen
+		 * the end of the previous one.  Spit it out anyway before
+		 * starting on the new one.
+		 */
+		if (last[fd] != SLT_SessionClose)
+			vsb_printf(ob[fd], "%5d %-12s %c %s\n",
+			    fd, "Interrupted", type, VSL_tags[tag]);
+		h_order_finish(fd);
+	}
+
+	last[fd] = tag;
+
 	switch (tag) {
 	case SLT_VCL_call:
 		if (flg[fd] & F_INVCL)
@@ -130,10 +168,7 @@ h_order(void *priv, enum shmlogtag tag, unsigned fd, unsigned len, unsigned spec
 		else
 			flg[fd] |= F_INVCL;
 		vsb_printf(ob[fd], "%5d %-12s %c %.*s",
-		    fd, VSL_tags[tag],
-		    ((spec & VSL_S_CLIENT) ? 'c' : \
-		    (spec & VSL_S_BACKEND) ? 'b' : '-'),
-		    len, ptr);
+		    fd, VSL_tags[tag], type, len, ptr);
 		return (0);
 	case SLT_VCL_trace:
 	case SLT_VCL_return:
@@ -151,20 +186,13 @@ h_order(void *priv, enum shmlogtag tag, unsigned fd, unsigned len, unsigned spec
 		flg[fd] &= ~F_INVCL;
 	}
 	vsb_printf(ob[fd], "%5d %-12s %c %.*s\n",
-	    fd, VSL_tags[tag],
-	    ((spec & VSL_S_CLIENT) ? 'c' : (spec & VSL_S_BACKEND) ? 'b' : '-'),
-	    len, ptr);
+	    fd, VSL_tags[tag], type, len, ptr);
 	switch (tag) {
 	case SLT_ReqEnd:
 	case SLT_BackendClose:
 	case SLT_BackendReuse:
 	case SLT_StatSess:
-		vsb_finish(ob[fd]);
-		if (vsb_len(ob[fd]) > 1 &&
-		    (match_tag == -1 || flg[fd] & F_MATCH))
-			printf("%s\n", vsb_data(ob[fd]));
-		flg[fd] &= ~F_MATCH;
-		vsb_clear(ob[fd]);
+		h_order_finish(fd);
 		break;
 	default:
 		break;