Hi Varnish Users, I¹m seeing some weird behavior in a load test I¹m doing. When stressing our backends up to the area of 2000 req/s, I¹m seeing sporadic 503 responses from varnish. My understanding is, that this would happen if, for instance, no backend is available.
I¹m looking at my logs like that: varnishlog -n essearchvarnish -q "RespStatus >= 500 or BerespStatus >= 500³ A sample 503 output is that one: * << Request >> 27632438 - Begin req 27630762 rxreq - Timestamp Start: 1426066874.412913 0.000000 0.000000 - Timestamp Req: 1426066874.412913 0.000000 0.000000 - ReqStart 10.47.28.251 49641 - ReqMethod GET - ReqURL /svc/somequery?string?documents=1 - ReqProtocol HTTP/1.1 - ReqHeader Accept-Language: de - ReqHeader User-Agent: Java1.8.0 - ReqHeader Host: essearch.local - ReqHeader Connection: Keep-Alive - ReqHeader Accept-Encoding: gzip - VCL_call RECV - VCL_return hash - VCL_call HASH - VCL_return lookup - Debug "XXXX HIT-FOR-PASS" - HitPass 2201620563 - VCL_call PASS - VCL_return fetch - Link bereq 27632439 pass - Timestamp Fetch: 1426066874.412967 0.000054 0.000054 - Timestamp Process: 1426066874.412979 0.000066 0.000012 - RespHeader Date: Wed, 11 Mar 2015 09:41:14 GMT - RespHeader Server: Varnish - RespHeader X-Varnish: 27632438 - RespProtocol HTTP/1.1 - RespStatus 503 - RespReason Service Unavailable - RespReason Service Unavailable - VCL_call SYNTH - RespHeader Content-Type: text/html; charset=utf-8 - RespHeader Retry-After: 5 - VCL_return deliver - RespHeader Content-Length: 282 - Debug "RES_MODE 2" - RespHeader Connection: keep-alive - Timestamp Resp: 1426066874.413033 0.000119 0.000053 - ReqAcct 454 0 454 212 282 494 - End What makes me wonder is, that this output is missing the actual backend request attempts. Also, printing "RespReason Service Unavailable³ twice in a row?!? Why? So in a second shell, on the same varnish at the same time, I have this query running: varnishlog -b -n essearchvarnish -q "RespStatus >= 500 or BerespStatus >= 500³ I added the -b parameter to see the backend requests. However, I get no output at all. So it seems varnish would throw the 503 without asking the backend? Or, hopefully more likely, I¹m not using varnishlog correctly?! This is varnish 4.0.3-2~wheezy. How can I print client and backend connections in one go? Doing using the -c and -b parameter in parallel doesn¹t produce any output (while in my other console, I still have the first query which produces the above output). I know that around 2000 req/s my backends are getting a bit slower ( up to 2 seconds for responses), but this should not hit any internal timeouts of varnish, right? I haven¹t changed the default timeouts. Also the backends itself are healthy. I¹m watching the backends (several tomcats) directly, and also from the varnish perspective via watch -n1 varnishadm -n essearchvarnish backend.list Everything looks healthy. Any help for how I could dig into this further would be appreciated :-) I guess it boils down to better use varnishlog on my side. Like getting client and backend connections for a request at the same time and not by using varnishlog in two shells differently. best regards, Marian _______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
