Mailing List Archive

Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux)
Hi,

I have a problem with Varnish (2.1.5) not adding 'X-Forwarded-For' and an 'X-Varnish' to a large portion of the backend requests it makes. It looks like a bug in Varnish.

The details:

A Varnish 2.1.5 / 64bit Linux server is placed in front of 4 backends. The site it is serving has been running for a very long time already without problems. Recently I got an email from a web-developper telling me that he saw a large portion of the requests coming from the Varnish server without X-Forwarded-For headers. When I researched the subject I discovered he was right. This situation was probably already like this for a long time, too.

Varnish is supposed to add an 'X-Forwarded-For' and an 'X-Varnish' header to each request it does to a backend, when not in 'pipe mode' that is. When using the varnishlog tool I can see that Varnish says that it is doing this for every request it issues.

When I started inspecting tcpdumps of the traffic on the Varnish server I discovered the following: Varnish is handling more traffic than it shows in its logs. The traffic that is not showing up in the logs is the same traffic that the backends see as having no XFF and no X-Varnish header. After closer inspection of the tcpdumps I found out that each time that Varnish receives a response containing a 'Keep-Alive:' and / or 'Connection: Keep-Alive' header, it will stop sending the XFF and X-Varnish headers. It looks very much like Varnish enters 'pipe mode' at that moment, because the traffic without those headers is also not registered in its logs.

What's also noticable is that the 'Host:' header, that was first with a lower case 'h' is now spelled with an uppercase 'H'. And also, suddenly a 'Connection: Keep-Alive' header is added to all requests coming from Varnish. These are more indicators that Varnish is now in a kind of 'pipe mode'. I checked to see if the VCL code for the site is configured to go into pipe mode : It is most definitely not.

I've added an real life example of a tcpdump below, showing the first few requests going well, and after a certain response, containing the 'Keep-Alive:' and 'Connection: Keep-Alive' header, Varnish stops acting as it should, and starts ommiting the XFF and X-Varnish headers. This is one example of, but I have lots more similar examples for the same site. In the example, I've placed a properly visible marker to indicate where things go wrong.

Can someone tell me what's going on here? This looks very much like a bug in Varnish, but I have been searching for the cause of this problem for so long already, that I might very well have overlooked something terribly obvious. Any help will be greatly appreciated.

Cheers,

Johnny


#=== The following is text exctracted from a tcpdump on the Varnish server's network interface ============


GET <masked>
Accept: application/javascript, */*;q=0.8
Referer: <masked>
Accept-Language: nl-NL
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
If-Modified-Since: Tue, 13 Dec 2011 19:56:19 GMT
Cookie: <masked>
Accept-Encoding: gzip
host: <masked>
X-Varnish: 1148200324
X-Forwarded-For: <masked>

HTTP/1.1 200 OK
Date: Tue, 13 Dec 2011 20:05:00 GMT
Last-Modified: Tue, 13 Dec 2011 20:05:00 GMT
Cache-Control: private, must-revalidate
Expires: Wed, 16 Aug 2000 10:00:00 GMT
Content-Type: text/html;charset=utf-8
Vary: Accept-Encoding
Content-Encoding: gzip
P3P: policyref="/w3c/p3p.xml", CP="NON DSP COR CURa OUR NOR"
Content-Length: 3917

<data>

GET <masked>
Accept: */*
Referer: <masked>
Accept-Language: nl
UA-CPU: x86
If-Modified-Since: Tue, 13 Dec 2011 20:04:19 GMT
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; GTB7.2; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; .NET CLR 1.1.4322; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)
Cookie: <masked>
Accept-Encoding: gzip
host: <masked>
X-Varnish: 1148200496
X-Forwarded-For: <masked>

HTTP/1.1 200 OK
Date: Tue, 13 Dec 2011 20:05:00 GMT
Last-Modified: Tue, 13 Dec 2011 20:05:00 GMT
Cache-Control: private, must-revalidate
Expires: Wed, 16 Aug 2000 10:00:00 GMT
Content-Type: text/html;charset=utf-8
Vary: Accept-Encoding
Content-Encoding: gzip
P3P: policyref="/w3c/p3p.xml", CP="NON DSP COR CURa OUR NOR"
Content-Length: 3917

<data>

POST <masked>
Accept: */*
Content-Type: application/x-www-form-urlencoded
X-Requested-With: XMLHttpRequest
Referer: <masked>
Accept-Language: nl
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Content-Length: 112
Connection: Keep-Alive
Cache-Control: no-cache
Cookie: <masked>
Accept-Encoding: gzip
host: <masked>
X-Varnish: 1148201219
X-Forwarded-For: <masked>

<data>

HTTP/1.1 200 OK
Date: Tue, 13 Dec 2011 20:05:00 GMT
Content-Type: text/html; charset=utf-8
Cache-Control: max-age=0
Expires: Tue, 13 Dec 2011 20:05:00 GMT
P3P: policyref="/w3c/p3p.xml", CP="NON DSP COR CURa OUR NOR"
Vary: Accept-Encoding
Content-Encoding: gzip
Content-Length: 732
Keep-Alive: timeout=3, max=9999
Connection: Keep-Alive

<data>

<==========================================================================>
<=== From here on, Varnish no longer appends either X-Varnish or X-Forwarded-For headers to backend requests. ===>
<==========================================================================>

GET <masked>
Accept: image/png, image/svg+xml, image/*;q=0.8, */*;q=0.5
Referer: <masked>
Accept-Language: nl-NL
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: <masked>
Connection: Keep-Alive
Cookie: <masked>

HTTP/1.1 200 OK
Date: Tue, 13 Dec 2011 20:05:01 GMT
Server: Apache
Last-Modified: Tue, 13 Dec 2011 08:12:33 GMT
ETag: "303232-197-4b3f4d02f5e40"
Accept-Ranges: bytes
Content-Length: 407
Cache-Control: max-age=86400
Expires: Wed, 14 Dec 2011 20:05:01 GMT
P3P: policyref="/w3c/p3p.xml", CP="NON DSP COR CURa OUR NOR"
Keep-Alive: timeout=3, max=9998
Connection: Keep-Alive
Content-Type: image/gif

<data>

GET <masked>
Accept: text/css
Referer: <masked>
Accept-Language: nl-NL
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
Accept-Encoding: gzip, deflate
Host: <masked>
Connection: Keep-Alive
Cookie: <masked>

HTTP/1.1 200 OK
Date: Tue, 13 Dec 2011 20:05:07 GMT
Server: Apache
Last-Modified: Tue, 13 Dec 2011 08:12:33 GMT
ETag: "59b39-3f9-4b3f4d02f5e40"
Accept-Ranges: bytes
Cache-Control: max-age=86400
Expires: Wed, 14 Dec 2011 20:05:07 GMT
Vary: Accept-Encoding
Content-Encoding: gzip
P3P: policyref="/w3c/p3p.xml", CP="NON DSP COR CURa OUR NOR"
Content-Length: 506
Keep-Alive: timeout=3, max=9997
Connection: Keep-Alive
Content-Type: text/css

<data>


_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux) [ In reply to ]
Hi Johnny,

On Wed, Dec 14, 2011 at 12:16 AM, Johnny Halfmoon <jhalfmoon@milksnot.com>wrote:

> Hi,
>
> I have a problem with Varnish (2.1.5) not adding 'X-Forwarded-For' and an
> 'X-Varnish' to a large portion of the backend requests it makes.


Typically this happens when people are piping requests and forget to set a
Connection: close. So then the TCP socket stays open and the browsers keeps
on talking to the backend. Is this what is going on with you?



--
Per Buer, CEO
Phone: +47 21 98 92 61 / Mobile: +47 958 39 117 / Skype: per.buer
*Varnish makes websites fly!*
Whitepapers <http://www.varnish-software.com/whitepapers> |
Video<http://www.youtube.com/watch?v=x7t2Sp174eI> |
Twitter <https://twitter.com/varnishsoftware>
Re: Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux) [ In reply to ]
On 12/14/2011 09:36 AM, Per Buer wrote:
> Hi Johnny,
>
> On Wed, Dec 14, 2011 at 12:16 AM, Johnny Halfmoon <jhalfmoon@milksnot.com <mailto:jhalfmoon@milksnot.com>> wrote:
>
> Hi,
>
> I have a problem with Varnish (2.1.5) not adding 'X-Forwarded-For' and an 'X-Varnish' to a large portion of the backend requests it makes.
>
>
> Typically this happens when people are piping requests and forget to set a Connection: close. So then the TCP socket stays open and the browsers keeps on talking to the backend. Is this what is going on with you?
>
Unfortunately, no. Pipe connections are correctly configured to close by this config :

sub vcl_pipe
{
set req.http.connection = "close";
}

And besides that: When I monitor all requests for this site (lets call it site X), I see only GET and POST requests and nothing that should trigger 'pipe mode' for this site. There are other sites also running on the Varnish server, some of which trigger 'pipe mode' sometimes, but these sites use seperate backends, so this should be of no influence to the traffic to site X.

Cheers,

Johnny


_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux) [ In reply to ]
On Wed, Dec 14, 2011 at 10:39:51AM +0100, Johnny Halfmoon wrote:
> >
> >Typically this happens when people are piping requests and forget to set a
> >Connection: close. So then the TCP socket stays open and the browsers keeps
> >on talking to the backend. Is this what is going on with you?
> >
> Unfortunately, no. Pipe connections are correctly configured to close by this
> config :

varnishlog and corresponding pcap dumps would be very helpful.

--
Andreas

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux) [ In reply to ]
On 12/14/2011 10:49 AM, Andreas Plesner Jacobsen wrote:
> On Wed, Dec 14, 2011 at 10:39:51AM +0100, Johnny Halfmoon wrote:
>>> Typically this happens when people are piping requests and forget to set a
>>> Connection: close. So then the TCP socket stays open and the browsers keeps
>>> on talking to the backend. Is this what is going on with you?
>>>
>> Unfortunately, no. Pipe connections are correctly configured to close by this
>> config :
> varnishlog and corresponding pcap dumps would be very helpful.
>
In my initial post there's already a real-life example snapshot from a single TCP session between the Varnish server and a backend, illustrating the issue. As for a Varnishlog; the backend requests are not logged, so those do not show up in the log. I'll prepare an integrated backend/frontend varnishlog, to post here, where at least the frontend requests and responses will be visible. And I'll see if I can post the tcpdump corresponding to that varnishlog too. The dumps are huge, even on short time spans, so they tend to take a while to be processed.



_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Possible bug: Missing X-Forwarded-For and X-Varnish headers (Varnish 2.1.5 64bit Linux) [ In reply to ]
On 12/14/2011 09:36 AM, Per Buer wrote:
> Hi Johnny,
>
> On Wed, Dec 14, 2011 at 12:16 AM, Johnny Halfmoon <jhalfmoon@milksnot.com <mailto:jhalfmoon@milksnot.com>> wrote:
>
> Hi,
>
> I have a problem with Varnish (2.1.5) not adding 'X-Forwarded-For' and an 'X-Varnish' to a large portion of the backend requests it makes.
>
>
> Typically this happens when people are piping requests and forget to set a Connection: close. So then the TCP socket stays open and the browsers keeps on talking to the backend. Is this what is going on with you?
>
> Per Buer, CEO

Hi,

A bit late, but I would like to update this thread by closing it correctly with a summary of the solution. This issue has been resolved very quickly and correctly by the Varnish support team, on the same day that the issue was reported. Thanks guys!

The problem was not caused by a bug in Varnish at all, but by 2 errors in my VCL files, which indeed, as Per suggested, led to pipe connections remaining open. This is what happened:

1. POST requests were accidentally being handled by pipe(). I completely missed this in the config, and was convinced pipe was not being used. This was my config:

if ( req.request != "GET"&&
req.request != "HEAD"&&
req.request != "PURGE") {
return(pipe);
}

2. To add to this error, another config errror was causing whole groups of requests to be piped because piped requests were not being 'closed'. But I thought they were, so I was looking elsewhere for the solution. I happened to be a silly typo. I was doing this:

vcl_pipe() { set req.http.connection = "close"; }

which is wrong and instead I should have been doing this:

vcl_pipe() { set bereq.http.connection = "close"; }

So in the end, closing the pipe connections properly fixed the problem. Again, thanks for the great support you guys!

Cheers,

Johnny



_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc