Figured some people will find this useful, until varnishncsa gets full
LogFormat support.
I've expanded Emil Isberg's initial path on the following items:
List of what I added/fixed:
- Fixed segfault in %s,%>s, when these where not found in shmlog
- Fixed segfault in %{VarnishR}i, when df_H, Protocol version, was not
found, http defaults to HTTP/1.0
- Added %D, ( proc_time + xmit_time ) in microseconds
- Added $T, same as above, but in seconds
- Added %V, faked as %{Host}i ( different meaning in apache, but usually
meant as vhost )
- Added %{Age}i, age of object being served. Quite useful, as you can graph
things like average age of served pages, cache hit ratios, etc etc.
I attach a diff against stock 2.0.4 varnish, I've tested this against
several multi-gigabyte varnish native logs, as well as have it run for a few
days now, with no issues.
-Javier
--- varnishncsa.c 2009-10-26 01:37:52.000000000 -0400
+++ varnishncsa.c.orig 2009-10-26 00:24:03.000000000 -0400
@@ -27,7 +27,7 @@
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*
- * $Id: varnishncsa.c 4003 2009-03-27 12:13:31Z tfheen $
+ * $Id$
*
* Obtain log data from the shared memory log, order it by session ID, and
* display it in Apache / NCSA combined log format:
@@ -97,14 +97,11 @@
char *df_s; /* %s, Status */
struct tm df_t; /* %t, Date and time */
char *df_u; /* %u, Remote user */
- int df_D; /* %D, The time taken to serve the request, in microseconds */
- char *df_Age; /* %{Age}i Age of served object */
int bogus; /* bogus request */
} **ll;
static size_t nll;
static int prefer_x_forwarded_for = 0;
-static const char *L_fmt = "%h %l %u %t \"%{VarnishR}i\" %>s %b \"%{Referer}i\" \"%{User-agent}i\"";
static int
isprefix(const char *str, const char *prefix, const char *end,
@@ -270,7 +267,6 @@
{
const char *end, *next;
long l;
- double idle_t,proc_t,xmit_t;
time_t t;
assert(spec & VSL_S_CLIENT);
@@ -310,12 +306,6 @@
lp->bogus = 1;
else
lp->df_s = trimline(ptr, end);
-
- break;
-
- case SLT_TxHeader:
- if (isprefix(ptr, "age:", end, &next))
- lp->df_Age = trimline(next, end);
break;
case SLT_RxHeader:
@@ -346,11 +336,10 @@
break;
case SLT_ReqEnd:
- if (sscanf(ptr, "%*u %*u.%*u %ld.%*u %lf %lf %lf", &l, &idle_t, &proc_t, &xmit_t) != 4) {
+ if (sscanf(ptr, "%*u %*u.%*u %ld.", &l) != 1) {
lp->bogus = 1;
} else {
t = l;
- lp->df_D= (proc_t + xmit_t) * 1000000;
localtime_r(&t, &lp->df_t);
}
/* got it all */
@@ -364,208 +353,13 @@
return (1);
}
-/*
- * print stuff according to fmt
- * try to be as much compliant with apache as possible
- * http://httpd.apache.org/docs/2.0/mod/mod_log_config.html#formats
- *
- * Note that return value is used to step a pointer
- * Must not return anything less than 1
- */
-static int
-fmt_print(FILE *fo, const char *fmt, unsigned spec, struct logline *lp)
-{
- char *q, tbuf[64];
- if (!strncmp(fmt, "%%", 2)) { /* %% */
- fputc('%', fo);
- return 2;
- }
-
- if (!strncmp(fmt, "%h", 2)) { /* %h */
- if (!lp->df_h && spec & VSL_S_BACKEND)
- fprintf(fo, "127.0.0.1");
- else if (lp->df_X_Forwarded_For && prefer_x_forwarded_for)
- fprintf(fo, "%s", lp->df_X_Forwarded_For);
- else
- fprintf(fo, "%s", lp->df_h ? lp->df_h : "-");
- return 2;
- }
-
- if (!strncmp(fmt, "%l", 2)) { /* %l */
- fprintf(fo, "-");
- return 2;
- }
-
- if (!strncmp(fmt, "%u", 2)) { /* %u: decode authorization string */
- if (lp->df_u != NULL) {
- char *rubuf;
- size_t rulen;
-
- base64_init();
- rulen = ((strlen(lp->df_u) + 3) * 4) / 3;
- rubuf = malloc(rulen);
- assert(rubuf != NULL);
- base64_decode(rubuf, rulen, lp->df_u);
- q = strchr(rubuf, ':');
- if (q != NULL)
- *q = '\0';
- fprintf(fo, "%s", rubuf);
- free(rubuf);
- } else {
- fprintf(fo, "-");
- }
- return 2;
- }
-
- if (!strncmp(fmt, "%t", 2)) { /* %t */
- strftime(tbuf, sizeof tbuf, "[%d/%b/%Y:%T %z]", &lp->df_t);
- fprintf(fo, "%s", tbuf);
- return 2;
- }
-
- if (!strncmp(fmt, "%{VarnishR}i", 12)) { /* %{VarnishR}i */
- /*
- * Fake "%r". This would be a lot easier if Varnish
- * normalized the request URL.
- */
- fprintf(fo, "%s ", lp->df_m);
- if (lp->df_Host) {
- if (strncmp(lp->df_Host, "http://";, 7) != 0)
- fprintf(fo, "http://";);
- fprintf(fo, "%s", lp->df_Host);
- }
- fprintf(fo, "%s ", lp->df_Uq);
- fprintf(fo, "%s", lp->df_H ? lp->df_H : "HTTP/1.0");
- return 12;
- }
-
- if (!strncmp(fmt, "%r", 2)) { /* %r */
- fprintf(fo, "%s %s %s", lp->df_m, lp->df_Uq, lp->df_H);
- return 2;
- }
-
- if (!strncmp(fmt, "%{Host}i", 8)) { /* %{Host}i */
- fprintf(fo, "%s", lp->df_Host ? lp->df_Host : "-");
- return 8;
- }
-
- if (!strncmp(fmt, "%V", 2)) { /* %V */
- fprintf(fo, "%s", lp->df_Host ? lp->df_Host : "-");
- return 2;
- }
-
-
- if (!strncmp(fmt, "%>s", 3)) { /* %>s should be the same as %s */
- fprintf(fo, "%s", lp->df_s ? lp->df_s : "-" );
- return 3;
- }
-
- if (!strncmp(fmt, "%s", 2)) { /* %s */
- fprintf(fo, "%s", lp->df_s ? lp->df_s : "-");
- return 2;
- }
-
- if (!strncmp(fmt, "%B", 2)) { /* %B */
- fprintf(fo, "%s", lp->df_b ? lp->df_b : "0");
- return 2;
- }
-
- if (!strncmp(fmt, "%b", 2)) { /* %b */
- fprintf(fo, "%s", lp->df_b ? lp->df_b : "-");
- return 2;
- }
-
- if (!strncmp(fmt, "%{Referer}i", 11)) { /* %{Referer}i */
- fprintf(fo, "%s",
- lp->df_Referer ? lp->df_Referer : "-");
- return 11;
- }
-
- if (!strncmp(fmt, "%{User-agent}i", 14)) { /* %{User-agent}i */
- fprintf(fo, "%s",
- lp->df_User_agent ? lp->df_User_agent : "-");
- return 14;
- }
-
- if (!strncmp(fmt, "%D", 2)) { /* %D : The time taken to serve the request, in microseconds. */
- if ( lp->df_D > 0 ) {
- fprintf(fo, "%i", lp->df_D);
- } else {
- fputc('-',fo);
- }
- return 2;
- }
-
- if (!strncmp(fmt, "%T", 2)) { /* %T : The time taken to serve the request, in seconds. */
- if ( lp->df_D > 0 ) {
- fprintf(fo, "%.2f", (float)lp->df_D/1000000);
- } else {
- fputc('-',fo);
- }
- return 2;
- }
-
-
- if (!strncmp(fmt, "%{Age}i", 7)) { /* %{Age}i: Age of object being served */
- fprintf(fo, "%s",
- lp->df_Age ? lp->df_Age : "-");
- return 7;
- }
-
- if (!strncmp(fmt, "%X", 2)) { /* %X : Connection status when response is completed: X,+,- */
- fputc('-',fo); /* TODO */
- return 2;
- }
-
- if (!strncmp(fmt, "%{Cookie}i", 10)) { /* %{Cookie}i : Cookie value as the client specifies it */
- fputc('-',fo); /* TODO */
- return 10;
- }
-
- if (!strncmp(fmt, "%{Set-Cookie}o", 14)) { /* %{Set-Cookie}o : Cookie value as we send to the cookie */
- fputc('-',fo); /* TODO */
- return 14;
- }
-
- /* fallback */
- fputc(*fmt, fo);
- return 1; /* never return anything less than 1 */
-}
-
-/*
- * Handle the backslash-escaped characters.
- * Try to confirm to basic printf syntax
- */
-static int
-bsl_print(FILE *fo, const char *fmt)
-{
- fmt++;
- switch(*fmt) {
- case '\\': fputc('\\', fo); return 2;break;
- case 'a': fputc('\a', fo); return 2;break;
- case 'b': fputc('\b', fo); return 2;break;
- case 'f': fputc('\f', fo); return 2;break;
- case 'n': fputc('\n', fo); return 2;break;
- case 'r': fputc('\r', fo); return 2;break;
- case 't': fputc('\t', fo); return 2;break;
- case 'v': fputc('\v', fo); return 2;break;
- case '"': fputc('"', fo); return 2;break;
- case '\'': fputc('\'', fo); return 2; break;
- case 'c': /* break parsing */ return strlen(fmt);break;
- }
- /* TODO: implement support for '\ddd', '\0ddd', '\xdd' */
-
- /* nothing match, output what we got */
- fputc('\\', fo);
- return 1; /* never return anything less than 1 */
-}
-
static int
h_ncsa(void *priv, enum shmlogtag tag, unsigned fd,
unsigned len, unsigned spec, const char *ptr)
{
struct logline *lp;
FILE *fo = priv;
+ char *q, tbuf[64];
if (fd >= nll) {
struct logline **newll = ll;
@@ -605,16 +399,66 @@
if (!lp->bogus) {
fo = priv;
- ptr = L_fmt;
- while (ptr && *ptr) {
- switch(*ptr) {
- printf("string = %s", ptr);
- case '%': ptr += fmt_print(fo, ptr, spec, lp);break;
- case '\\': ptr += bsl_print(fo, ptr);break;
- default: fputc(*ptr, fo);ptr++;break;
- }
+ /* %h */
+ if (!lp->df_h && spec & VSL_S_BACKEND)
+ fprintf(fo, "127.0.0.1 ");
+ else if (lp->df_X_Forwarded_For && prefer_x_forwarded_for)
+ fprintf(fo, "%s ", lp->df_X_Forwarded_For);
+ else
+ fprintf(fo, "%s ", lp->df_h ? lp->df_h : "-");
+
+ /* %l */
+ fprintf(fo, "- ");
+
+ /* %u: decode authorization string */
+ if (lp->df_u != NULL) {
+ char *rubuf;
+ size_t rulen;
+
+ base64_init();
+ rulen = ((strlen(lp->df_u) + 3) * 4) / 3;
+ rubuf = malloc(rulen);
+ assert(rubuf != NULL);
+ base64_decode(rubuf, rulen, lp->df_u);
+ q = strchr(rubuf, ':');
+ if (q != NULL)
+ *q = '\0';
+ fprintf(fo, "%s ", rubuf);
+ free(rubuf);
+ } else {
+ fprintf(fo, "- ");
+ }
+
+ /* %t */
+ strftime(tbuf, sizeof tbuf, "[%d/%b/%Y:%T %z]", &lp->df_t);
+ fprintf(fo, "%s ", tbuf);
+
+ /*
+ * Fake "%r". This would be a lot easier if Varnish
+ * normalized the request URL.
+ */
+ fprintf(fo, "\"%s ", lp->df_m);
+ if (lp->df_Host) {
+ if (strncmp(lp->df_Host, "http://";, 7) != 0)
+ fprintf(fo, "http://";);
+ fprintf(fo, "%s", lp->df_Host);
}
- fputc('\n', fo); /* end of line */
+ fprintf(fo, "%s ", lp->df_Uq);
+ fprintf(fo, "%s\" ", lp->df_H);
+
+ /* %s */
+ fprintf(fo, "%s ", lp->df_s);
+
+ /* %b */
+ fprintf(fo, "%s ", lp->df_b ? lp->df_b : "-");
+
+ /* %{Referer}i */
+ fprintf(fo, "\"%s\" ",
+ lp->df_Referer ? lp->df_Referer : "-");
+
+ /* %{User-agent}i */
+ fprintf(fo, "\"%s\"\n",
+ lp->df_User_agent ? lp->df_User_agent : "-");
/* flush the stream */
fflush(fo);
@@ -687,7 +531,7 @@
vd = VSL_New();
- while ((c = getopt(argc, argv, VSL_ARGS "aDn:P:Vw:fL:")) != -1) {
+ while ((c = getopt(argc, argv, VSL_ARGS "aDn:P:Vw:f")) != -1) {
switch (c) {
case 'a':
a_flag = 1;
@@ -710,10 +554,6 @@
case 'w':
w_arg = optarg;
break;
- case 'L':
- L_fmt = optarg;
- /* TODO: should check that the format is usable */
- break;
default:
if (VSL_Arg(vd, c, optarg) > 0)
break;
_______________________________________________
varnish-dev mailing list
varnish-dev@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-dev
