r2571 - in branches/1.1: . bin/varnishlog

[des at projects.linpro.no]

Author: des
Date: 2008-03-08 16:43:28 +0100 (Sat, 08 Mar 2008)
New Revision: 2571

Modified:
   branches/1.1/
   branches/1.1/bin/varnishlog/varnishlog.c
Log:
Merged revisions 2569 via svnmerge from 
svn+ssh://projects.linpro.no/svn/varnish/trunk/varnish-cache

........
  r2569 | des | 2008-03-08 16:42:23 +0100 (Sat, 08 Mar 2008) | 7 lines
  
  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.
........



Property changes on: branches/1.1
___________________________________________________________________
Name: svnmerge-integrated
   - /trunk/varnish-cache:1-1722,1727-1729,1733,1738,1743-1777,1779-1798,1800-1815,1817,1819,1823,1830-1838,1846,1853-1855,1857-1859,1862,1865-1868,1871-1880,1883-1884,1886,1888-1889,1896,1898,1902-1905,1907,1909,1912-1916,1920-1928,1935-1939,1941-1949,1955,1957-1958,1967-1968,1970-1974,1976-1977,1984,1986-1989,1991-1998,2026,2031-2033,2057,2077-2080,2086,2088,2091,2097,2106-2107,2116,2133,2154,2173,2181,2206-2207,2211-2212,2215-2245,2256-2262,2270-2271,2275,2285-2286,2288-2291,2295-2301,2304-2327,2337,2357-2359,2361-2364,2366,2374-2386,2404,2414-2415,2421-2422,2426,2432-2434,2444-2445,2447,2453-2461,2467,2492-2505,2520-2524,2545,2563-2565
   + /trunk/varnish-cache:1-1722,1727-1729,1733,1738,1743-1777,1779-1798,1800-1815,1817,1819,1823,1830-1838,1846,1853-1855,1857-1859,1862,1865-1868,1871-1880,1883-1884,1886,1888-1889,1896,1898,1902-1905,1907,1909,1912-1916,1920-1928,1935-1939,1941-1949,1955,1957-1958,1967-1968,1970-1974,1976-1977,1984,1986-1989,1991-1998,2026,2031-2033,2057,2077-2080,2086,2088,2091,2097,2106-2107,2116,2133,2154,2173,2181,2206-2207,2211-2212,2215-2245,2256-2262,2270-2271,2275,2285-2286,2288-2291,2295-2301,2304-2327,2337,2357-2359,2361-2364,2366,2374-2386,2404,2414-2415,2421-2422,2426,2432-2434,2444-2445,2447,2453-2461,2467,2492-2505,2520-2524,2545,2563-2565,2569

Modified: branches/1.1/bin/varnishlog/varnishlog.c
===================================================================
--- branches/1.1/bin/varnishlog/varnishlog.c	2008-03-08 15:43:00 UTC (rev 2570)
+++ branches/1.1/bin/varnishlog/varnishlog.c	2008-03-08 15:43:28 UTC (rev 2571)
@@ -82,6 +82,7 @@
 
 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)
 
@@ -89,6 +90,18 @@
 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)
 {
 	unsigned u;
@@ -108,9 +121,13 @@
 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 @@
 	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 @@
 		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 @@
 		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;