RespReason Service Unavailable but no backend connection attempt?!

[Jason Price]

I'm not as familiar with varnish4 (I need vmods), but in varnish 3,
backends need to be specified with timeouts:

backend backend31 {
        .host = "10.24.14.112";
        .port = "80";
        .probe = backendcheck;
        .connect_timeout = 3s;
        .first_byte_timeout = 5s;
        .between_bytes_timeout = 2s;
}

If your backends are averaging 2+ seconds, then your outliers are probably
5-6 seconds... and that could easily trip the defaults (though I don't
recall off-hand what they are).

--Jason

On Wed, Mar 11, 2015 at 6:22 AM, Hettwer, Marian <mhettwer at team.mobile.de>
wrote:

> 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
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20150312/ed7de70c/attachment.html>