Skip to content

V
varnish-cache
Commit 9c130267 authored by Pål Hermunn Johansen's avatar Pål Hermunn Johansen
Browse files
Options

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.
parent e171090e
Hide whitespace changes
Inline Side-by-side
Showing with 138 additions and 25 deletions
bin/varnishncsa/varnishncsa.c
View file @ 9c130267
......@@ -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);
......
bin/varnishncsa/varnishncsa_options.h
View file @ 9c130267
......@@ -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
......
doc/sphinx/reference/varnishncsa.rst
View file @ 9c130267
......@@ -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@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
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