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

[Johnny Halfmoon]

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>