Hi, We had a strange incident happy on a varnish node today, which resulted in a sustained extra 60 reqs/sec for around 4.5 hrs of identical sequential requests with the *request* being "HTTP/1.1 302 Found". The particular IP address had been browsing normally, until they got the following response:
<snip> 491 TxProtocol c HTTP/1.1 491 TxStatus c 200 491 TxResponse c OK 491 TxHeader c Content-Type: text/javascript;charset=UTF-8 491 TxHeader c Cache-Control: no-cache, no-store, max-age=0, must-revalidate, private, no-transform 491 TxHeader c Expires: Fri, 29 Apr 2011 05:00:00 GMT 491 TxHeader c Content-Length: 2715 491 TxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 TxHeader c X-Varnish: 747013197 491 TxHeader c Age: 0 491 TxHeader c Via: 1.1 varnish 491 TxHeader c Connection: keep-alive 491 Length c 2715 491 ReqEnd c 747013197 1322654693.630128860 1322654693.636650801 0.030966997 0.006455421 0.000066519 This looks absolutely fine - we sent them a short javascript snippet that shouldn't be cached. This is a request which happens thousands of times an hour with no issue. What happened next is strange: The response we'd just sent them (above) came back to varnish as a fresh request: 491 ReqStart c 86.166.aaa.bbb 56853 747013203 491 RxRequest c HTTP/1.1 491 RxURL c 200 491 RxProtocol c OK 491 RxHeader c Content-Type: text/javascript;charset=UTF-8 491 RxHeader c Cache-Control: no-cache, no-store, max-age=0, must-revalidate, private, no-transform 491 RxHeader c Expires: Fri, 29 Apr 2011 05:00:00 GMT 491 RxHeader c Content-Length: 2715 491 RxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 RxHeader c X-Varnish: 747013197 491 RxHeader c Age: 0 491 RxHeader c Via: 1.1 varnish 491 RxHeader c Connection: keep-alive 491 RxHeader c X-Antivirus: avast! 4 491 RxHeader c X-Antivirus-Status: Clean Look how we *received* an X-Varnish header, with the same ID as the previous response. But, it must have gone via the client, as an additional header was added - the X-Antivirus. This then was a miss in Varnish, and fell through to our backends, which responds with a redirect if requested with an invalid hostname: 491 VCL_call c recv pass 491 VCL_call c hash hash 491 VCL_call c pass pass 491 Backend c 823 primarypool web01 491 TTL c 747013203 RFC 120 1322654693 0 0 0 0 491 VCL_call c fetch 491 TTL c 747013203 VCL 0 1322654694 491 VCL_return c deliver 491 ObjProtocol c HTTP/1.1 491 ObjStatus c 302 491 ObjResponse c Found 491 ObjHeader c Date: Wed, 30 Nov 2011 11:04:54 GMT 491 ObjHeader c Location: http://www.mainsite.com 491 ObjHeader c Content-Length: 201 491 ObjHeader c Content-Type: text/html; charset=iso-8859-1 491 ObjHeader c Cache-Control: max-age=0, public 491 ObjHeader c X-Varnish-Status: u 491 VCL_call c deliver deliver 491 TxProtocol c HTTP/1.1 491 TxStatus c 302 491 TxResponse c Found 491 TxHeader c Location: http://www.mainsite.com 491 TxHeader c Content-Type: text/html; charset=iso-8859-1 491 TxHeader c Cache-Control: max-age=0, public 491 TxHeader c X-Varnish-Status: u 491 TxHeader c Content-Length: 201 491 TxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 TxHeader c X-Varnish: 747013203 491 TxHeader c Age: 0 491 TxHeader c Via: 1.1 varnish 491 TxHeader c Connection: keep-alive 491 Length c 201 491 ReqEnd c 747013203 1322654693.676038265 1322654693.701058388 0.039387465 0.024901628 0.000118494 And then this pattern continued for over 4 hrs. 491 ReqStart c 86.166.aaa.bbb 56853 747013208 491 RxRequest c HTTP/1.1 491 RxURL c 302 491 RxProtocol c Found 491 RxHeader c Location: http://www.mainsite.com 491 RxHeader c Content-Type: text/html; charset=iso-8859-1 491 RxHeader c Cache-Control: max-age=0, public 491 RxHeader c X-Varnish-Status: u 491 RxHeader c Content-Length: 201 491 RxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 RxHeader c X-Varnish: 747013203 491 RxHeader c Age: 0 491 RxHeader c Via: 1.1 varnish 491 RxHeader c Connection: keep-alive 491 VCL_call c recv pass 491 VCL_call c hash hash 491 VCL_call c pass pass 491 Backend c 115 primarypool web02 491 TTL c 747013208 RFC 120 1322654693 0 0 0 0 491 VCL_call c fetch 491 TTL c 747013208 VCL 0 1322654694 491 VCL_return c deliver 491 ObjProtocol c HTTP/1.1 491 ObjStatus c 302 491 ObjResponse c Found 491 ObjHeader c Date: Wed, 30 Nov 2011 11:04:54 GMT 491 ObjHeader c Location: http://www.mainsite.com 491 ObjHeader c Content-Length: 201 491 ObjHeader c Content-Type: text/html; charset=iso-8859-1 491 ObjHeader c Cache-Control: max-age=0, public 491 ObjHeader c X-Varnish-Status: u 491 VCL_call c deliver deliver 491 TxProtocol c HTTP/1.1 491 TxStatus c 302 491 TxResponse c Found 491 TxHeader c Location: http://www.mainsite.com 491 TxHeader c Content-Type: text/html; charset=iso-8859-1 491 TxHeader c Cache-Control: max-age=0, public 491 TxHeader c X-Varnish-Status: u 491 TxHeader c Content-Length: 201 491 TxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 TxHeader c X-Varnish: 747013208 491 TxHeader c Age: 0 491 TxHeader c Via: 1.1 varnish 491 TxHeader c Connection: keep-alive 491 Length c 201 491 ReqEnd c 747013208 1322654693.774824381 1322654693.775967836 0.073765993 0.001085758 0.000057697 491 ReqStart c 86.166.aaa.bbb 56853 747013209 491 RxRequest c HTTP/1.1 491 RxURL c 302 491 RxProtocol c Found 491 RxHeader c Location: http://www.mainsite.com 491 RxHeader c Content-Type: text/html; charset=iso-8859-1 491 RxHeader c Cache-Control: max-age=0, public 491 RxHeader c X-Varnish-Status: u 491 RxHeader c Content-Length: 201 491 RxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 RxHeader c X-Varnish: 747013208 491 RxHeader c Age: 0 491 RxHeader c Via: 1.1 varnish 491 RxHeader c Connection: keep-alive 491 VCL_call c recv pass 491 VCL_call c hash hash 491 VCL_call c pass pass 491 Backend c 115 primarypool web03 491 TTL c 747013209 RFC 120 1322654693 0 0 0 0 491 VCL_call c fetch 491 TTL c 747013209 VCL 0 1322654694 491 VCL_return c deliver 491 ObjProtocol c HTTP/1.1 491 ObjStatus c 302 491 ObjResponse c Found 491 ObjHeader c Date: Wed, 30 Nov 2011 11:04:55 GMT 491 ObjHeader c Location: http://www.mainsite.com 491 ObjHeader c Content-Length: 201 491 ObjHeader c Content-Type: text/html; charset=iso-8859-1 491 ObjHeader c Cache-Control: max-age=0, public 491 ObjHeader c X-Varnish-Status: u 491 VCL_call c deliver deliver 491 TxProtocol c HTTP/1.1 491 TxStatus c 302 491 TxResponse c Found 491 TxHeader c Location: http://www.mainsite.com 491 TxHeader c Content-Type: text/html; charset=iso-8859-1 491 TxHeader c Cache-Control: max-age=0, public 491 TxHeader c X-Varnish-Status: u 491 TxHeader c Content-Length: 201 491 TxHeader c Date: Wed, 30 Nov 2011 12:04:53 GMT 491 TxHeader c X-Varnish: 747013209 491 TxHeader c Age: 0 491 TxHeader c Via: 1.1 varnish 491 TxHeader c Connection: keep-alive 491 Length c 201 491 ReqEnd c 747013209 1322654693.791796923 1322654693.793078899 0.015829086 0.001143694 0.000138283 Has anyone seen anything like this before? How would you reduce the likelihood of this circular (almost) DoS attach in Varnish? Should we drop inbound requests if they contain an RxHeader of X-Varnish? Our vcl_recv is fairly complex, but ultimately boils down to return(lookup) if it doesn't match any earlier criteria, so that's the path being hit. We didn't see a significant change in network bandwidth usage, and at 60 requests per second, I wonder if this tight loop happened internally within Varnish, rather than going all the way to the end IP address. 60 sequential requests per second is one every 16ms. The IP address is an ADSL connection in the UK, so it *could* be 16ms away, but that's at the very low end of what's the likely ping time. But, on the other hand, 16ms is a long time for Varnish to be in a loop in the datacentre, given that the backend web servers are on the same gigabit LAN as Varnish and our backends are fast for this request. We're running varnish-2.1.5-1.el6.x86_64 on CentOS 6.0 (2.6.32-71.el6.x86_64) Thanks, Rob _______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
