RespReason Service Unavailable but no backend connection attempt?!

[Hettwer, Marian]

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