[master] 86b3f9f Log proxy related messages on the session, not on the request.
Martin Blix Grydeland
martin at varnish-software.com
Tue Oct 27 15:28:41 CET 2015
commit 86b3f9feca54af49ce194f5d6bed9e4dcfa54971
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date: Fri Oct 23 15:51:58 2015 +0200
Log proxy related messages on the session, not on the request.
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
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
More information about the varnish-commit
mailing list