Skip to content

V
varnish-cache
Commit 2175fdf6 authored by Martin Blix Grydeland's avatar Martin Blix Grydeland
Browse files
Options

Merge r5162: Make varnishncsa only consider log information between the open... 

Merge r5162: Make varnishncsa only consider log information between the open and close log tags for a connection, and clear the collected log data on seeing the open tag. This resolves an issue with log data where varnishncsa would consider a set of data as bogus because of extra data in the log belonging to the previous connection.

Support case 164.



git-svn-id: http://www.varnish-cache.org/svn/branches/2.1@5164 d4fa192b-c00b-0410-8231-f00ffab90ce4
parent e574df8e
Hide whitespace changes
Inline Side-by-side
Showing with 193 additions and 136 deletions
bin/varnishncsa/varnishncsa.c
View file @ 2175fdf6
...@@ -96,7 +96,8 @@ static struct logline { ...@@ -96,7 +96,8 @@ static struct logline {
char *df_s; /* %s, Status */ char *df_s; /* %s, Status */
struct tm df_t; /* %t, Date and time */ struct tm df_t; /* %t, Date and time */
char *df_u; /* %u, Remote user */ char *df_u; /* %u, Remote user */
int bogus; /* bogus request */ int active; /* Is log line in an active trans */
int complete; /* Is log line complete */
} **ll; } **ll;
static size_t nll; static size_t nll;
...@@ -177,6 +178,25 @@ trimline(const char *str, const char *end) ...@@ -177,6 +178,25 @@ trimline(const char *str, const char *end)
return (p); return (p);
} }
static void
clean_logline(struct logline *lp)
{
#define freez(x) do { if (x) free(x); x = NULL; } while (0);
freez(lp->df_H);
freez(lp->df_Host);
freez(lp->df_Referer);
freez(lp->df_Uq);
freez(lp->df_User_agent);
freez(lp->df_X_Forwarded_For);
freez(lp->df_b);
freez(lp->df_h);
freez(lp->df_m);
freez(lp->df_s);
freez(lp->df_u);
#undef freez
memset(lp, 0, sizeof *lp);
}
static int static int
collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec, collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec,
const char *ptr, unsigned len) const char *ptr, unsigned len)
...@@ -188,52 +208,72 @@ collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec, ...@@ -188,52 +208,72 @@ collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec,
switch (tag) { switch (tag) {
case SLT_BackendOpen: case SLT_BackendOpen:
if (lp->df_h != NULL) if(lp->active || lp->df_h != NULL) {
lp->bogus = 1; /* New start for active line,
clean it and start from scratch */
clean_logline(lp);
}
lp->active = 1;
if (isprefix(ptr, "default", end, &next))
lp->df_h = trimfield(next, end);
else else
if (isprefix(ptr, "default", end, &next)) lp->df_h = trimfield(ptr, end);
lp->df_h = trimfield(next, end);
else
lp->df_h = trimfield(ptr, end);
break; break;
case SLT_TxRequest: case SLT_TxRequest:
if (lp->df_m != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_m != NULL) {
lp->df_m = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_m = trimline(ptr, end);
break; break;
case SLT_TxURL: case SLT_TxURL:
if (lp->df_Uq != NULL) if(!lp->active)
lp->bogus = 1; break;
else if(lp->df_Uq != NULL) {
lp->df_Uq = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_Uq = trimline(ptr, end);
break; break;
case SLT_TxProtocol: case SLT_TxProtocol:
if (lp->df_H != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_H != NULL) {
lp->df_H = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_H = trimline(ptr, end);
break; break;
case SLT_RxStatus: case SLT_RxStatus:
if (lp->df_s != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_s != NULL) {
lp->df_s = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_s = trimline(ptr, end);
break; break;
case SLT_RxHeader: case SLT_RxHeader:
if(!lp->active)
break;
if (isprefix(ptr, "content-length:", end, &next)) if (isprefix(ptr, "content-length:", end, &next))
lp->df_b = trimline(next, end); lp->df_b = trimline(next, end);
else if (isprefix(ptr, "date:", end, &next) && else if (isprefix(ptr, "date:", end, &next) &&
strptime(next, "%a, %d %b %Y %T", &lp->df_t) == NULL) strptime(next, "%a, %d %b %Y %T", &lp->df_t) == NULL) {
lp->bogus = 1; clean_logline(lp);
}
break; break;
case SLT_TxHeader: case SLT_TxHeader:
if(!lp->active)
break;
if (isprefix(ptr, "user-agent:", end, &next)) if (isprefix(ptr, "user-agent:", end, &next))
lp->df_User_agent = trimline(next, end); lp->df_User_agent = trimline(next, end);
else if (isprefix(ptr, "referer:", end, &next)) else if (isprefix(ptr, "referer:", end, &next))
...@@ -249,14 +289,16 @@ collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec, ...@@ -249,14 +289,16 @@ collect_backend(struct logline *lp, enum shmlogtag tag, unsigned spec,
case SLT_BackendReuse: case SLT_BackendReuse:
case SLT_BackendClose: case SLT_BackendClose:
if(!lp->active)
break;
/* got it all */ /* got it all */
return (0); lp->complete = 1;
break;
default: default:
break; break;
} }
/* more to come */
return (1); return (1);
} }
...@@ -273,41 +315,57 @@ collect_client(struct logline *lp, enum shmlogtag tag, unsigned spec, ...@@ -273,41 +315,57 @@ collect_client(struct logline *lp, enum shmlogtag tag, unsigned spec,
switch (tag) { switch (tag) {
case SLT_ReqStart: case SLT_ReqStart:
if (lp->df_h != NULL) if(lp->active || lp->df_h != NULL) {
lp->bogus = 1; /* New start for active line,
else clean it and start from scratch */
lp->df_h = trimfield(ptr, end); clean_logline(lp);
}
lp->active = 1;
lp->df_h = trimfield(ptr, end);
break; break;
case SLT_RxRequest: case SLT_RxRequest:
if (lp->df_m != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_m != NULL) {
lp->df_m = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_m = trimline(ptr, end);
break; break;
case SLT_RxURL: case SLT_RxURL:
if (lp->df_Uq != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_Uq != NULL) {
lp->df_Uq = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_Uq = trimline(ptr, end);
break; break;
case SLT_RxProtocol: case SLT_RxProtocol:
if (lp->df_H != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_H != NULL) {
lp->df_H = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_H = trimline(ptr, end);
break; break;
case SLT_TxStatus: case SLT_TxStatus:
if(!lp->active)
break;
if (lp->df_s != NULL) if (lp->df_s != NULL)
lp->bogus = 1; clean_logline(lp);
else else
lp->df_s = trimline(ptr, end); lp->df_s = trimline(ptr, end);
break; break;
case SLT_RxHeader: case SLT_RxHeader:
if(!lp->active)
break;
if (isprefix(ptr, "user-agent:", end, &next)) if (isprefix(ptr, "user-agent:", end, &next))
lp->df_User_agent = trimline(next, end); lp->df_User_agent = trimline(next, end);
else if (isprefix(ptr, "referer:", end, &next)) else if (isprefix(ptr, "referer:", end, &next))
...@@ -322,33 +380,42 @@ collect_client(struct logline *lp, enum shmlogtag tag, unsigned spec, ...@@ -322,33 +380,42 @@ collect_client(struct logline *lp, enum shmlogtag tag, unsigned spec,
break; break;
case SLT_Length: case SLT_Length:
if (lp->df_b != NULL) if(!lp->active)
lp->bogus = 1; break;
else if (lp->df_b != NULL) {
lp->df_b = trimline(ptr, end); clean_logline(lp);
break;
}
lp->df_b = trimline(ptr, end);
break; break;
case SLT_SessionClose: case SLT_SessionClose:
if(!lp->active)
break;
if (strncmp(ptr, "pipe", len) == 0 || if (strncmp(ptr, "pipe", len) == 0 ||
strncmp(ptr, "error", len) == 0) strncmp(ptr, "error", len) == 0) {
lp->bogus = 1; clean_logline(lp);
break;
}
break; break;
case SLT_ReqEnd: case SLT_ReqEnd:
if(!lp->active)
break;
if (sscanf(ptr, "%*u %*u.%*u %ld.", &l) != 1) { if (sscanf(ptr, "%*u %*u.%*u %ld.", &l) != 1) {
lp->bogus = 1; clean_logline(lp);
} else { break;
t = l;
localtime_r(&t, &lp->df_t);
} }
t = l;
localtime_r(&t, &lp->df_t);
/* got it all */ /* got it all */
return (0); lp->complete = 1;
break;
default: default:
break; break;
} }
/* more to come */
return (1); return (1);
} }
...@@ -379,105 +446,95 @@ h_ncsa(void *priv, enum shmlogtag tag, unsigned fd, ...@@ -379,105 +446,95 @@ h_ncsa(void *priv, enum shmlogtag tag, unsigned fd,
lp = ll[fd]; lp = ll[fd];
if (spec & VSL_S_BACKEND) { if (spec & VSL_S_BACKEND) {
if (collect_backend(lp, tag, spec, ptr, len)) collect_backend(lp, tag, spec, ptr, len);
return (reopen);
} else if (spec & VSL_S_CLIENT) { } else if (spec & VSL_S_CLIENT) {
if (collect_client(lp, tag, spec, ptr, len)) collect_client(lp, tag, spec, ptr, len);
return (reopen);
} else { } else {
/* huh? */ /* huh? */
return (reopen); return (reopen);
} }
if(!lp->complete)
return (reopen);
#if 0 #if 0
/* non-optional fields */ /* non-optional fields */
if (!lp->df_m || !lp->df_Uq || !lp->df_H || !lp->df_s) if (!lp->df_m || !lp->df_Uq || !lp->df_H || !lp->df_s) {
lp->bogus = 1; clean_logline(lp);
return (reopen);
}
#endif #endif
if (!lp->bogus) { /* We have a complete data set - log a line */
fo = priv;
fo = priv;
/* %h */
if (!lp->df_h && spec & VSL_S_BACKEND) /* %h */
fprintf(fo, "127.0.0.1 "); if (!lp->df_h && spec & VSL_S_BACKEND)
else if (lp->df_X_Forwarded_For && prefer_x_forwarded_for) fprintf(fo, "127.0.0.1 ");
fprintf(fo, "%s ", lp->df_X_Forwarded_For); else if (lp->df_X_Forwarded_For && prefer_x_forwarded_for)
else fprintf(fo, "%s ", lp->df_X_Forwarded_For);
fprintf(fo, "%s ", lp->df_h ? lp->df_h : "-"); else
fprintf(fo, "%s ", lp->df_h ? lp->df_h : "-");
/* %l */
/* %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, "- "); fprintf(fo, "- ");
}
/* %u: decode authorization string */ /* %t */
if (lp->df_u != NULL) { strftime(tbuf, sizeof tbuf, "[%d/%b/%Y:%T %z]", &lp->df_t);
char *rubuf; fprintf(fo, "%s ", tbuf);
size_t rulen;
/*
base64_init(); * Fake "%r". This would be a lot easier if Varnish
rulen = ((strlen(lp->df_u) + 3) * 4) / 3; * normalized the request URL.
rubuf = malloc(rulen); */
assert(rubuf != NULL); fprintf(fo, "\"%s ", lp->df_m);
base64_decode(rubuf, rulen, lp->df_u); if (lp->df_Host) {
q = strchr(rubuf, ':'); if (strncmp(lp->df_Host, "http://", 7) != 0)
if (q != NULL) fprintf(fo, "http://");
*q = '\0'; fprintf(fo, "%s", lp->df_Host);
fprintf(fo, "%s ", rubuf); }
free(rubuf); fprintf(fo, "%s ", lp->df_Uq);
} else { fprintf(fo, "%s\" ", lp->df_H);
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);
}
fprintf(fo, "%s ", lp->df_Uq);
fprintf(fo, "%s\" ", lp->df_H);
/* %s */ /* %s */
fprintf(fo, "%s ", lp->df_s); fprintf(fo, "%s ", lp->df_s);
/* %b */ /* %b */
fprintf(fo, "%s ", lp->df_b ? lp->df_b : "-"); fprintf(fo, "%s ", lp->df_b ? lp->df_b : "-");
/* %{Referer}i */ /* %{Referer}i */
fprintf(fo, "\"%s\" ", fprintf(fo, "\"%s\" ",
lp->df_Referer ? lp->df_Referer : "-"); lp->df_Referer ? lp->df_Referer : "-");
/* %{User-agent}i */ /* %{User-agent}i */
fprintf(fo, "\"%s\"\n", fprintf(fo, "\"%s\"\n",
lp->df_User_agent ? lp->df_User_agent : "-"); lp->df_User_agent ? lp->df_User_agent : "-");
/* flush the stream */ /* flush the stream */
fflush(fo); fflush(fo);
}
/* clean up */ /* clean up */
#define freez(x) do { if (x) free(x); x = NULL; } while (0); clean_logline(lp);
freez(lp->df_H);
freez(lp->df_Host);
freez(lp->df_Referer);
freez(lp->df_Uq);
freez(lp->df_User_agent);
freez(lp->df_X_Forwarded_For);
freez(lp->df_b);
freez(lp->df_h);
freez(lp->df_m);
freez(lp->df_s);
freez(lp->df_u);
#undef freez
memset(lp, 0, sizeof *lp);
return (reopen); return (reopen);
} }
......
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