[master] 9c13026 Backend mode in varnishncsa

PÃ¥l Hermunn Johansen hermunn at varnish-software.com
Mon Apr 25 15:57:06 CEST 2016


commit 9c13026752259bb4d317fdbd9bd420b7142f9019
Author: Pål Hermunn Johansen <hermunn at varnish-software.com>
Date:   Mon Apr 25 12:43:54 2016 +0200

    Backend mode in varnishncsa
    
    A new mode, backend mode, in varnishncsa is introduced. It lets you
    log trafic from varnish to the backends. The normal (default) mode is
    now named "client mode" and can be explicitly selected using -c. You
    can run varnishncsa in backend mode in addition to varnishncsa in
    client mode, but it is also possible to run in mixed mode by
    specifying both -b and -c.
    
    New formatter added: %{Varnish:side}x will be either "b" or "c",
    depending on where the request was made.

diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c
index 885743d..326b6ae 100644
--- a/bin/varnishncsa/varnishncsa.c
+++ b/bin/varnishncsa/varnishncsa.c
@@ -50,6 +50,7 @@
 #include <errno.h>
 #include <stdarg.h>
 #include <stdint.h>
+#include <limits.h>
 #include <ctype.h>
 #include <time.h>
 #include <math.h>
@@ -125,6 +126,8 @@ VTAILQ_HEAD(watch_head, watch);
 struct ctx {
 	/* Options */
 	int			a_opt;
+	int			b_opt;
+	int			c_opt;
 	char			*w_arg;
 
 	FILE			*fo;
@@ -134,11 +137,12 @@ struct ctx {
 
 	/* State */
 	struct watch_head	watch_vcl_log;
-	struct watch_head	watch_reqhdr;
-	struct watch_head	watch_resphdr;
+	struct watch_head	watch_reqhdr; /* also bereqhdr */
+	struct watch_head	watch_resphdr; /* also beresphdr */
 	struct fragment		frag[F__MAX];
 	const char		*hitmiss;
 	const char		*handling;
+	const char		*side;
 } CTX;
 
 static void
@@ -658,6 +662,10 @@ parse_format(const char *format)
 					addf_strptr(&CTX.handling);
 					break;
 				}
+				if (!strcmp(buf, "Varnish:side")) {
+					addf_strptr(&CTX.side);
+					break;
+				}
 				if (!strncmp(buf, "VCL_Log:", 8)) {
 					addf_vcl_log(buf + 8, "");
 					break;
@@ -717,7 +725,8 @@ frag_fields(int force, const char *b, const char *e, ...)
 	field = va_arg(ap, int);
 	frag = va_arg(ap, struct fragment *);
 	for (n = 1, q = b; q < e; n++) {
-		assert(field > 0);
+		/* caller must sort the fields, or this loop will not work: */
+		assert(field >= n);
 		AN(frag);
 
 		p = q;
@@ -786,14 +795,25 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 	unsigned tag;
 	const char *b, *e, *p;
 	struct watch *w;
-	int i, skip;
+	int i, skip, be_mark;
 	(void)vsl;
 	(void)priv;
 
+#define BACKEND_MARKER (INT_MAX / 2 + 1)
+	assert(BACKEND_MARKER >= VSL_t__MAX);
+
 	for (t = pt[0]; t != NULL; t = *++pt) {
 		CTX.gen++;
-		if (t->type != VSL_t_req)
-			/* Only look at client requests */
+
+		/* Consider client requests only if in client mode.
+		   Consider backend requests only if in backend mode. */
+		if (t->type == VSL_t_req && CTX.c_opt) {
+			CTX.side = "c";
+			be_mark = 0;
+		} else if (t->type == VSL_t_bereq && CTX.b_opt) {
+			CTX.side = "b";
+			be_mark = BACKEND_MARKER;
+		} else
 			continue;
 		if (t->reason == VSL_r_esi)
 			/* Skip ESI requests */
@@ -808,7 +828,8 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 			while (e > b && e[-1] == '\0')
 				e--;
 
-			switch (tag) {
+			switch (tag + be_mark) {
+			case SLT_HttpGarbage + BACKEND_MARKER:
 			case SLT_HttpGarbage:
 				skip = 1;
 				break;
@@ -818,14 +839,21 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 				    4, &CTX.frag[F_O],
 				    0, NULL);
 				break;
+			case (SLT_BackendStart + BACKEND_MARKER):
+				frag_fields(1, b, e,
+				    1, &CTX.frag[F_h],
+				    0, NULL);
+				break;
 			case SLT_ReqStart:
 				frag_fields(0, b, e,
 				    1, &CTX.frag[F_h],
 				    0, NULL);
 				break;
+			case (SLT_BereqMethod + BACKEND_MARKER):
 			case SLT_ReqMethod:
 				frag_line(0, b, e, &CTX.frag[F_m]);
 				break;
+			case (SLT_BereqURL + BACKEND_MARKER):
 			case SLT_ReqURL:
 				p = memchr(b, '?', e - b);
 				if (p == NULL)
@@ -833,12 +861,15 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 				frag_line(0, b, p, &CTX.frag[F_U]);
 				frag_line(0, p, e, &CTX.frag[F_q]);
 				break;
+			case (SLT_BereqProtocol + BACKEND_MARKER):
 			case SLT_ReqProtocol:
 				frag_line(0, b, e, &CTX.frag[F_H]);
 				break;
+			case (SLT_BerespStatus + BACKEND_MARKER):
 			case SLT_RespStatus:
 				frag_line(1, b, e, &CTX.frag[F_s]);
 				break;
+			case (SLT_BereqAcct + BACKEND_MARKER):
 			case SLT_ReqAcct:
 				frag_fields(0, b, e,
 				    3, &CTX.frag[F_I],
@@ -846,22 +877,26 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 				    6, &CTX.frag[F_O],
 				    0, NULL);
 				break;
+			case (SLT_Timestamp + BACKEND_MARKER):
 			case SLT_Timestamp:
 				if (isprefix(b, "Start:", e, &p)) {
 					frag_fields(0, p, e, 1,
 					    &CTX.frag[F_tstart], 0, NULL);
 
 				} else if (isprefix(b, "Resp:", e, &p) ||
-					isprefix(b, "PipeSess:", e, &p)) {
+					isprefix(b, "PipeSess:", e, &p) ||
+					isprefix(b, "BerespBody:", e, &p)) {
 					frag_fields(0, p, e, 1,
 					    &CTX.frag[F_tend], 0, NULL);
 
 				} else if (isprefix(b, "Process:", e, &p) ||
-					isprefix(b, "Pipe:", e, &p)) {
+					isprefix(b, "Pipe:", e, &p) ||
+					isprefix(b, "Beresp:", e, &p)) {
 					frag_fields(0, p, e, 2,
 					    &CTX.frag[F_ttfb], 0, NULL);
 				}
 				break;
+			case (SLT_BereqHeader + BACKEND_MARKER):
 			case SLT_ReqHeader:
 				if (isprefix(b, "Host:", e, &p))
 					frag_line(0, p, e, &CTX.frag[F_host]);
@@ -869,6 +904,8 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 				    isprefix(p, "basic", e, &p))
 					frag_line(0, p, e, &CTX.frag[F_auth]);
 				break;
+			case (SLT_VCL_call + BACKEND_MARKER):
+				break;
 			case SLT_VCL_call:
 				if (!strcasecmp(b, "recv")) {
 					CTX.hitmiss = "-";
@@ -890,6 +927,8 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 					CTX.handling = "synth";
 				}
 				break;
+			case (SLT_VCL_return + BACKEND_MARKER):
+				break;
 			case SLT_VCL_return:
 				if (!strcasecmp(b, "restart")) {
 					skip = 1;
@@ -915,9 +954,11 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 					frag_line(0, p, e, &w->frag);
 				}
 			}
-			if (tag == SLT_ReqHeader)
+			if ((tag == SLT_ReqHeader && CTX.c_opt)
+			    || (tag == SLT_BereqHeader && CTX.b_opt))
 				process_hdr(&CTX.watch_reqhdr, b, e);
-			if (tag == SLT_RespHeader)
+			if ((tag == SLT_RespHeader && CTX.c_opt)
+			    || (tag == SLT_BerespHeader && CTX.b_opt))
 				process_hdr(&CTX.watch_resphdr, b, e);
 		}
 		if (skip)
@@ -980,6 +1021,14 @@ main(int argc, char * const *argv)
 			/* Append to file */
 			CTX.a_opt = 1;
 			break;
+		case 'b':
+			/* backend mode */
+			CTX.b_opt = 1;
+			break;
+		case 'c':
+			/* client mode */
+			CTX.c_opt = 1;
+			break;
 		case 'F':
 			/* Format string */
 			if (format != NULL)
@@ -1006,6 +1055,9 @@ main(int argc, char * const *argv)
 				usage(1);
 		}
 	}
+	/* default is client mode: */
+	if (!CTX.b_opt)
+		CTX.c_opt = 1;
 
 	if (optind != argc)
 		usage(1);
diff --git a/bin/varnishncsa/varnishncsa_options.h b/bin/varnishncsa/varnishncsa_options.h
index f141ad0..74b0f52 100644
--- a/bin/varnishncsa/varnishncsa_options.h
+++ b/bin/varnishncsa/varnishncsa_options.h
@@ -62,8 +62,20 @@
 	    " reopened allowing the old one to be rotated away. This"	\
 	    " option is required when running in daemon mode."		\
 	)
+#define NCSA_OPT_b							\
+	VOPT("b", "[-b]", "Backend mode",				\
+	    "Log backend requests. If -c is not specified, then only"	\
+	    " backend requests will trigger log lines."			\
+	)
+#define NCSA_OPT_c							\
+	VOPT("c", "[-c]", "Cient mode",					\
+	    "Log client requests. This is the default. If -b is"	\
+	    " specified, then -c is needed to also log client requests"	\
+	)
 
 NCSA_OPT_a
+NCSA_OPT_b
+NCSA_OPT_c
 VSL_OPT_C
 VUT_OPT_d
 VUT_OPT_D
diff --git a/doc/sphinx/reference/varnishncsa.rst b/doc/sphinx/reference/varnishncsa.rst
index 6475fcf..74078a5 100644
--- a/doc/sphinx/reference/varnishncsa.rst
+++ b/doc/sphinx/reference/varnishncsa.rst
@@ -34,6 +34,36 @@ The following options are available:
 
 .. include:: ../include/varnishncsa_options.rst
 
+MODES
+=====
+
+The default mode of varnishncsa is "client mode".  In this mode, the
+log will be similar to what a web server would produce in the absence
+of varnish.  Client mode can be explicitly selected by using -c.
+
+If the -b switch is specified, varnishncsa will operate in "backend
+mode".  In this mode, requests generated by varnish to the backends
+will be logged.  Unless -c is also specified, client requests received
+by varnish will be ignored.
+
+When running varnishncsa in both backend and client mode, it is
+strongly advised to include the format specifier %{Varnish:side}x to
+distinguish between backend and client requests.
+
+Client requests that results in a pipe (ie. return(pipe) in vcl), will
+not generate logging in backend mode. This is because varnish is not
+generating requests, but blindly passes on bytes in both directions.
+However, a varnishncsa instance running in normal mode can see this
+case by using the formatter %{Varnish:handling}x, which will be "pipe"
+(without the quotes).
+
+In backend mode, some of the fields in the format string get different
+meanings.  Most notably, the byte counting formatters (%b, %I, %O)
+considers varnish to be the client.
+
+It is possible to keep two varnishncsa instances running, one in
+backend mode, and one in client mode, logging to different files.
+
 FORMAT
 ======
 
@@ -49,20 +79,26 @@ Escape sequences \\n and \\t are supported.
 Supported formatters are:
 
 %b
-  Size of response in bytes, excluding HTTP headers.  In CLF format,
-  i.e. a '-' rather than a 0 when no bytes are sent.
+  In client mode, size of response in bytes, excluding HTTP headers.
+  In backend mode, the number of bytes received from the backend,
+  excluding HTTP headers.  In CLF format, i.e. a '-' rather than a 0
+  when no bytes are sent.
 
 %D
-  Time taken to serve the request, in microseconds.
+  In client mode, time taken to serve the request, in microseconds.
+  In backend mode, time from the request was sent to the entire body
+  had been received.
 
 %H
   The request protocol. Defaults to HTTP/1.0 if not known.
 
 %h
-  Remote host. Defaults to '-' if not known.
+  Remote host. Defaults to '-' if not known.  In backend mode this is
+  the IP of the backend server.
 
 %I
-  Total bytes received from client.
+  In client mode, total bytes received from client.  In backend mode,
+  total bytes sent to the backend.
 
 %{X}i
   The contents of request header X.
@@ -77,7 +113,8 @@ Supported formatters are:
   The contents of response header X.
 
 %O
-  Total bytes sent to client.
+  In client mode, total bytes sent to client.  In backend mode, total
+  bytes received from the backend.
 
 %q
   The query string, if no query string exists, an empty string.
@@ -87,17 +124,23 @@ Supported formatters are:
   may not be the request verbatim.
 
 %s
-  Status sent to the client
+  Status sent to the client.  In backend mode, status received from
+  the backend.
 
 %t
-  Time when the request was received, in HTTP date/time format.
+  In client mode, time when the request was received, in HTTP
+  date/time format.  In backend mode, time when the request was sent.
 
 %{X}t
-  Time when the request was received, in the format specified
-  by X. The time specification format is the same as for strftime(3).
+
+  In client mode, time when the request was received, in the format
+  specified by X.  In backend mode, time when the request was sent.
+  The time specification format is the same as for strftime(3).
 
 %T
-  Time taken to serve the request, in seconds.
+  In client mode, time taken to serve the request, in seconds.  In
+  backend mode, time from the request was sent to the entire body had
+  been received.
 
 %U
   The request URL without any query string. Defaults to '-' if not
@@ -111,7 +154,8 @@ Supported formatters are:
 
   Varnish:time_firstbyte
     Time from when the request processing starts until the first byte
-    is sent to the client.
+    is sent to the client.  For backend mode: Time from the request was
+    sent to the backend to the entire header had been received.
 
   Varnish:hitmiss
     Whether the request was a cache hit or miss. Pipe and pass are
@@ -121,6 +165,11 @@ Supported formatters are:
     How the request was handled, whether it was a cache hit, miss,
     pass, pipe or synth.
 
+  Varnish:side
+    Backend or client side. One of two values, "b" or "c" (without the
+    quotes), depending on where the request was made. In pure backend
+    or client mode, this field will be constant.
+
   VCL_Log:key
     Output value set by std.log("key:value") in VCL.
 
@@ -146,7 +195,7 @@ HISTORY
 The varnishncsa utility was developed by Poul-Henning Kamp in
 cooperation with Verdens Gang AS and Varnish Software AS. This manual page was
 initially written by Dag-Erling Smørgrav <des at des.no>, and later updated
-by Martin Blix Grydeland.
+by Martin Blix Grydeland and Pål Hermunn Johansen.
 
 
 COPYRIGHT
@@ -156,4 +205,4 @@ This document is licensed under the same licence as Varnish
 itself. See LICENCE for details.
 
 * Copyright (c) 2006 Verdens Gang AS
-* Copyright (c) 2006-2015 Varnish Software AS
+* Copyright (c) 2006-2016 Varnish Software AS



More information about the varnish-commit mailing list