Disclaimer: we are in a moment migrating some servers from Windows to Linux, so you will see some unusual architecture here.
I have the following communication between our backend servers:
Client -> Apache Httpd (decrypts SSL - running Windows Server) -> Varnish Cache (forward proxy and HTTP Cache - Running Ubuntu 16) -> Apache Tomcat (Application Server - Running Windows server).
We have something like 200 users active at peak time and an Ajax call that verify user connection every second.
From time to time, our clients receives a 503 (backend fetch failed - guru meditation) from this Ajax request. I first thought it would be some kind of application server slowdown so I increase timeouts as follows:
backend xxx {
.host = "<%= $HOST_API %>";
.port = "<%= $HOST_PORT %>";
.first_byte_timeout = 1200s;
.between_bytes_timeout = 1200s;
.connect_timeout = 10s;
}
But the problem continued to happen. So I investigated modifying the Apache Access Log to log the time the request spent on the backend:
The configuration was:
LogFormat "%h %l %u %t \"%r\" %>s %b **%T/%D**" commomWithTime
So the time will be shown as *TIME_IN_SECONDS/TIME_IN_MILISECONDS*
When I get a 503 error, I will receive the following line:
200.201.175.53 - - [11/Sep/2017:17:16:06 -0300] "GET /sistema/verificarDesconexao?_=1505154046861 HTTP/1.1" 503 286 **0/0**
So Apache is telling me Varnish returned a 503 error instantaneously! In this case, it is impossible to be a timeout error, right?
Here one Varnishlog message with the 503 error (I had to modify some sensitive parts):
* << BeReq >> 179699819
- Begin bereq 179699818 pass
- Timestamp Start: 1505161516.061772 0.000000 0.000000
- BereqMethod GET
- BereqURL /sistema/verificarDesconexao?_=1505153165280
- BereqProtocol HTTP/1.1
- BereqHeader Host: 10.1.1.135
- BereqHeader Accept: application/json, text/javascript, */*; q=0.01
- BereqHeader X-Requested-With: XMLHttpRequest
- BereqHeader User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36
- BereqHeader Content-Type: application/json;charset=ISO-8859-1
- BereqHeader Referer: https://www.sistema.com.br/sistema/
- BereqHeader Accept-Encoding: gzip, deflate, br
- BereqHeader Accept-Language: pt-BR,pt;q=0.8,en-US;q=0.6,en;q=0.4
- BereqHeader Cookie: JSESSIONID=0334D2460BD8E8AE9299E546AEB2838F; logo=Axis; idiomaSelecionado=pt_BR
- BereqHeader X-Forwarded-Host: www.sistema.com.br
- BereqHeader X-Forwarded-Server: www.sistema.com.br
- BereqHeader X-Forwarded-For: [IP], 10.1.1.177
- BereqHeader X-Varnish: 179699819
- VCL_call BACKEND_FETCH
- VCL_return fetch
- FetchError no backend connection
- Timestamp Beresp: 1505161516.062073 0.000301 0.000301
- Timestamp Error: 1505161516.062079 0.000307 0.000006
- BerespProtocol HTTP/1.1
- BerespStatus 503
- BerespReason Service Unavailable
- BerespReason Backend fetch failed
- BerespHeader Date: Mon, 11 Sep 2017 20:25:16 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: Mon, 11 Sep 2017 20:25:16 GMT
- ObjHeader Server: Varnish
- ObjHeader Content-Type: text/html; charset=utf-8
- ObjHeader Retry-After: 5
- Length 286
- BereqAcct 0 0 0 0 0 0
- End
Which other cases a Varnish 503 error would happen and how should I identify and solve it?
