[PATCH] Log proxy related messages on the session, not on the request.
Martin Blix Grydeland
martin at varnish-software.com
Fri Oct 23 15:55:37 CEST 2015
The proxy log records were attempted to be logged on the request' log
buffer, which at that point in time has not yet been set up and does
not posess a VXID. This caused VXID==0 log records to be inserted in
the beginning of the log for the first request on the session when
using proxy protocol, and subsequently the VSL to fail picking them
out as valid request log transactions.
Fix by logging the PROXY handling related messages on the session, in
which they belong.
Fixes: #1804
---
bin/varnishd/proxy/cache_proxy_proto.c | 34 +++++++++++++++--------------
bin/varnishtest/tests/r01804.vtc | 39 ++++++++++++++++++++++++++++++++++
2 files changed, 57 insertions(+), 16 deletions(-)
create mode 100644 bin/varnishtest/tests/r01804.vtc
diff --git a/bin/varnishd/proxy/cache_proxy_proto.c b/bin/varnishd/proxy/cache_proxy_proto.c
index 433581e..954beef 100644
--- a/bin/varnishd/proxy/cache_proxy_proto.c
+++ b/bin/varnishd/proxy/cache_proxy_proto.c
@@ -62,8 +62,9 @@ vpx_proto1(const struct worker *wrk, struct req *req)
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+ CHECK_OBJ_NOTNULL(req->sp, SESS_MAGIC);
- VSL(SLT_Debug, req->sp->fd, "PROXY1");
+ VSL(SLT_Debug, req->sp->vxid, "PROXY1");
q = strchr(req->htc->rxbuf_b, '\r');
if (q == NULL)
@@ -80,7 +81,7 @@ vpx_proto1(const struct worker *wrk, struct req *req)
for (i = 0; i < 5; i++) {
p = strchr(p, ' ');
if (p == NULL) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: Too few fields");
return (-1);
}
@@ -89,7 +90,7 @@ vpx_proto1(const struct worker *wrk, struct req *req)
}
if (strchr(p, ' ')) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: Too many fields");
return (-1);
}
@@ -102,7 +103,7 @@ vpx_proto1(const struct worker *wrk, struct req *req)
else if (!strcmp(fld[0], "TCP6"))
pfam = AF_INET6;
else {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: Wrong TCP[46] field");
return (-1);
}
@@ -113,14 +114,14 @@ vpx_proto1(const struct worker *wrk, struct req *req)
i = getaddrinfo(fld[1], fld[3], &hints, &res);
if (i != 0) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: Cannot resolve source address (%s)",
gai_strerror(i));
return (-1);
}
AZ(res->ai_next);
if (res->ai_family != pfam) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: %s got wrong protocol (%d)",
fld[0], res->ai_family);
freeaddrinfo(res);
@@ -134,14 +135,14 @@ vpx_proto1(const struct worker *wrk, struct req *req)
i = getaddrinfo(fld[2], fld[4], &hints, &res);
if (i != 0) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: Cannot resolve destination address (%s)",
gai_strerror(i));
return (-1);
}
AZ(res->ai_next);
if (res->ai_family != pfam) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY1: %s got wrong protocol (%d)",
fld[0], res->ai_family);
freeaddrinfo(res);
@@ -151,7 +152,7 @@ vpx_proto1(const struct worker *wrk, struct req *req)
AN(VSA_Build(sa, res->ai_addr, res->ai_addrlen));
freeaddrinfo(res);
- VSLb(req->vsl, SLT_Proxy, "1 %s %s %s %s",
+ VSL(SLT_Proxy, req->sp->vxid, "1 %s %s %s %s",
fld[1], fld[3], fld[2], fld[4]);
req->htc->pipeline_b = q;
return (0);
@@ -182,6 +183,7 @@ vpx_proto2(const struct worker *wrk, struct req *req)
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_NOTNULL(req, REQ_MAGIC);
+ CHECK_OBJ_NOTNULL(req->sp, SESS_MAGIC);
assert(req->htc->rxbuf_e - req->htc->rxbuf_b >= 16L);
l = vbe16dec(req->htc->rxbuf_b + 14);
@@ -191,7 +193,7 @@ vpx_proto2(const struct worker *wrk, struct req *req)
/* Version @12 top half */
if ((p[12] >> 4) != 2) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: bad version (%d)", p[12] >> 4);
return (-1);
}
@@ -205,7 +207,7 @@ vpx_proto2(const struct worker *wrk, struct req *req)
/* Proxied connection */
break;
default:
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: bad command (%d)", p[12] & 0x0f);
return (-1);
}
@@ -214,14 +216,14 @@ vpx_proto2(const struct worker *wrk, struct req *req)
switch(p[13]) {
case 0x00:
/* UNSPEC|UNSPEC, ignore proxy header */
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: Ignoring UNSPEC|UNSPEC addresses");
return (0);
case 0x11:
/* IPv4|TCP */
pfam = AF_INET;
if (l < 12) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: Ignoring short IPv4 addresses (%d)", l);
return (0);
}
@@ -230,14 +232,14 @@ vpx_proto2(const struct worker *wrk, struct req *req)
/* IPv6|TCP */
pfam = AF_INET6;
if (l < 36) {
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: Ignoring short IPv6 addresses (%d)", l);
return (0);
}
break;
default:
/* Ignore proxy header */
- VSLb(req->vsl, SLT_ProxyGarbage,
+ VSL(SLT_ProxyGarbage, req->sp->vxid,
"PROXY2: Ignoring unsupported protocol (0x%02x)", p[13]);
return (0);
}
@@ -286,7 +288,7 @@ vpx_proto2(const struct worker *wrk, struct req *req)
SES_Set_String_Attr(req->sp, SA_CLIENT_IP, hb);
SES_Set_String_Attr(req->sp, SA_CLIENT_PORT, pb);
- VSLb(req->vsl, SLT_Proxy, "2 %s %s %s %s", hb, pb, ha, pa);
+ VSL(SLT_Proxy, req->sp->vxid, "2 %s %s %s %s", hb, pb, ha, pa);
return (0);
}
diff --git a/bin/varnishtest/tests/r01804.vtc b/bin/varnishtest/tests/r01804.vtc
new file mode 100644
index 0000000..c6705eb
--- /dev/null
+++ b/bin/varnishtest/tests/r01804.vtc
@@ -0,0 +1,39 @@
+varnishtest "#1804: varnishapi transaction grouping fails for PROXY"
+
+server s1 {
+ rxreq
+ txresp
+} -start
+
+
+varnish v1 -proto "PROXY" -vcl+backend {
+} -start
+
+logexpect l1 -v v1 -d 0 -g session {
+ expect * * Begin {^sess .* PROXY$}
+ expect * = Proxy {^1 }
+ expect * * Begin {^req}
+ expect * * Begin {^sess .* PROXY$}
+ expect * = Proxy {^2 }
+ expect * * Begin {^req}
+} -start
+
+client c1 {
+ send "PROXY TCP4 1.2.3.4 5.6.7.8 1234 5678\r\n"
+ txreq
+ rxresp
+} -run
+
+client c2 {
+ # good IPv4
+ sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a"
+ sendhex "21 11 00 0c"
+ sendhex "01 02 03 04"
+ sendhex "05 06 07 08"
+ sendhex "09 0a"
+ sendhex "0b 0c"
+ txreq
+ rxresp
+} -run
+
+logexpect l1 -wait
--
2.1.4
More information about the varnish-dev
mailing list