Understanding 503s

Dridi Boukelmoune dridi at varni.sh
Thu Apr 15 07:21:01 UTC 2021


Hello,

For global timeouts:

https://varnish-cache.org/docs/trunk/reference/varnishd.html#run-time-parameters

They contain "timeout" in the name.

For VCL-defined timeouts:

https://varnish-cache.org/docs/trunk/reference/vcl-backend.html#timeout-attributes
https://varnish-cache.org/docs/trunk/reference/vcl-probe.html#attribute-timeout
https://varnish-cache.org/docs/trunk/reference/vcl-var.html

If the problem was a timeout, you would see this in the log:

    FetchError first byte timeout

If you are using apache httpd there´s a good chance that incoming
connections are closed after 5s of inactivity by default. But when
varnish pools backend connections, the default backend_idle_timeout is
60s so you may end up reusing a connection that was closed by your
httpd server. You should increase your keep-alive timeout to meet
varnish´s expectations.

https://httpd.apache.org/docs/2.4/mod/core.html#keepalivetimeout

Please note that varnish has a similar timeout_idle that defaults to
5s too. So stacking varnish servers can lead to the same problem if
you rely on the defaults.

Dridi

On Thu, Apr 15, 2021 at 6:27 AM Maninder Singh <mandys at gmail.com> wrote:
>
> Also, backend is apache 2.4
> and running php-fpm.
>
> On Thu, 15 Apr 2021 at 11:52, Maninder Singh <mandys at gmail.com> wrote:
>>
>> I have that defined as 2 minutes.
>> backend default {
>>     .host = "127.0.0.1";
>>     .port = "8080";
>>     .first_byte_timeout = 120s;
>> }
>>
>> That's why this error is puzzling.
>>
>> Any other timeouts ( connect ? ) etc to look at ?
>>
>> Also, in the above dump, how much time did it take ?
>>
>> To me it looks like it was closed within a second ?
>>
>>
>> -   BackendOpen    32 reload_2021-04-13T130756.default 127.0.0.1 8080 127.0.0.1 56176
>> -   BackendStart   127.0.0.1 8080
>> -   Timestamp      Bereq: 1618461577.074387 0.281276 0.281276
>> -   FetchError     http first read error: EOF
>> -   BackendClose   32 reload_2021-04-13T130756.default
>> -   Timestamp      Beresp: 1618461577.074430 0.281319 0.000043
>> -   Timestamp      Error: 1618461577.074434 0.281323 0.000004
>>
>> On Thu, 15 Apr 2021 at 11:42, Frands Bjerring Hansen <frands.hansen at team.blue> wrote:
>>>
>>> Look at the fetch error: http first read error: EOF
>>>
>>>
>>>
>>> Perhaps the backend closed the connection before sending any data or the first_byte_timeout defined for the backend has been reached. The default is 60 seconds.
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> / Frands Bjerring Hansen
>>> Head of Technology, Linux
>>> Office: +45 70 40 00 00
>>> frands.hansen at team.blue
>>>
>>> Operations - Linux
>>> team.blue Denmark A/S
>>> Højvangen 4
>>> 8660 Skanderborg
>>> Denmark
>>> CVR: 29412006
>>>
>>>
>>>
>>>
>>> On 15/04/2021, 08.08, "varnish-misc" <varnish-misc-bounces+fbh=zitcom.dk at varnish-cache.org> wrote:
>>>
>>> Hi,
>>>
>>> I need some help understanding why the below 503 is happening.
>>>
>>>
>>>
>>> I am logging 503s to a separate file and then querying as below.
>>>
>>>
>>>
>>> varnishlog -q "BerespStatus eq 503" -w /whatever/file
>>>
>>> varnishlog -r /whatever/file
>>>
>>>
>>>
>>> What's going wrong here ?
>>>
>>> What should I be looking at ?
>>>
>>>
>>>
>>> Please let me know.
>>>
>>>
>>>
>>> *   << BeReq    >> 45926757
>>>
>>> -   Begin          bereq 45926756 pass
>>>
>>> -   Timestamp      Start: 1618461576.793111 0.000000 0.000000
>>>
>>> -   BereqMethod    POST
>>>
>>> -   BereqURL       /index.php?&u=85&tr=aa
>>>
>>> -   BereqProtocol  HTTP/1.1
>>>
>>> -   BereqHeader    X-Forwarded-Proto: https
>>>
>>> -   BereqHeader    X-Forwarded-Port: 443
>>>
>>> -   BereqHeader    Host: graph.com <http://graph.com>
>>>
>>> -   BereqHeader    X-Amzn-Trace-Id: Root=1-xxx
>>>
>>> -   BereqHeader    Content-Length: 793
>>>
>>> -   BereqHeader    sec-ch-ua: "Google Chrome";v="89", "Chromium";v="89", ";Not A Brand";v="99"
>>>
>>> -   BereqHeader    accept: application/json, text/javascript, */*; q=0.01
>>>
>>> -   BereqHeader    sec-ch-ua-mobile: ?0
>>>
>>> -   BereqHeader    user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.128 Safari/537.36
>>>
>>> -   BereqHeader    content-type: application/x-www-form-urlencoded; charset=UTF-8
>>>
>>> -   BereqHeader    origin: https://mandy..com
>>>
>>> -   BereqHeader    sec-fetch-site: same-site
>>>
>>> -   BereqHeader    sec-fetch-mode: cors
>>>
>>> -   BereqHeader    sec-fetch-dest: empty
>>>
>>> -   BereqHeader    referer: https://mandy.com/
>>>
>>> -   BereqHeader    accept-encoding: gzip, deflate, br
>>>
>>> -   BereqHeader    accept-language: en-US,en;q=0.9
>>>
>>> -   BereqHeader    X-Forwarded-For: 103.67.157.20, 10.0.0.170
>>>
>>> -   BereqHeader    browser: other
>>>
>>> -   BereqHeader    serverIp: 10.0.3.237
>>>
>>> -   BereqHeader    serverId: abc01
>>>
>>> -   BereqHeader    X-Varnish: 45926757
>>>
>>> -   VCL_call       BACKEND_FETCH
>>>
>>> -   VCL_return     fetch
>>>
>>> -   BackendOpen    32 reload_2021-04-13T130756.default 127.0.0.1 8080 127.0.0.1 56176
>>>
>>> -   BackendStart   127.0.0.1 8080
>>>
>>> -   Timestamp      Bereq: 1618461577.074387 0.281276 0.281276
>>>
>>> -   FetchError     http first read error: EOF
>>>
>>> -   BackendClose   32 reload_2021-04-13T130756.default
>>>
>>> -   Timestamp      Beresp: 1618461577.074430 0.281319 0.000043
>>>
>>> -   Timestamp      Error: 1618461577.074434 0.281323 0.000004
>>>
>>> -   BerespProtocol HTTP/1.1
>>>
>>> -   BerespStatus   503
>>>
>>> -   BerespReason   Service Unavailable
>>>
>>> -   BerespReason   Backend fetch failed
>>>
>>> -   BerespHeader   Date: Thu, 15 Apr 2021 04:39:37 GMT
>>>
>>> -   BerespHeader   Server: Varnish
>>>
>>> -   VCL_call       BACKEND_ERROR
>>>
>>> -   BerespHeader   Content-Type: text/html; charset=utf-8
>>>
>>> -   BerespHeader   Retry-After: 5
>>>
>>> -   VCL_return     deliver
>>>
>>> -   Storage        malloc Transient
>>>
>>> -   ObjProtocol    HTTP/1.1
>>>
>>> -   ObjStatus      503
>>>
>>> -   ObjReason      Backend fetch failed
>>>
>>> -   ObjHeader      Date: Thu, 15 Apr 2021 04:39:37 GMT
>>>
>>> -   ObjHeader      Server: Varnish
>>>
>>> -   ObjHeader      Content-Type: text/html; charset=utf-8
>>>
>>> -   ObjHeader      Retry-After: 5
>>>
>>> -   Length         1288
>>>
>>> -   BereqAcct      948 793 1741 0 0 0
>>>
>>> -   End
>>>
>>>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc


More information about the varnish-misc mailing list