Varnish 503 nothing in Apache log

Question

We are getting random 503 responses from Varnish and when looking deeper in varnishlog we see that the backend server (Apache) is reported as a 503 but there is nothing in the apache access log.

How can we trace the cause of this issue?

From varnishlog

*   << Request  >> 42221068  
-   Begin          req 42221065 rxreq
-   Timestamp      Start: 1553163507.132639 0.000000 0.000000
-   Timestamp      Req: 1553163507.132639 0.000000 0.000000
-   ReqStart       172.31.19.159 14390
-   ReqMethod      POST
-   ReqURL         /path/to/request
-   ReqProtocol    HTTP/1.1
-   ReqHeader      X-Forwarded-For: 62.103.214.39
-   ReqHeader      X-Forwarded-Proto: https
-   ReqHeader      X-Forwarded-Port: 443
-   ReqHeader      Host: server.com
-   ReqHeader      X-Amzn-Trace-Id: Root=1-5c9364f3-26a603e3ce2f87d9923ed27e
-   ReqHeader      Content-Length: 53
-   ReqHeader      Accept: application/json
-   ReqHeader      Authorization: Bearer xxx
-   ReqHeader      Content-Type: application/json; charset=utf-8
-   ReqHeader      Cookie: PHPSESSID=o1f3010cuch8iu055stl6q1s03
-   ReqUnset       X-Forwarded-For: 62.103.214.39
-   ReqHeader      X-Forwarded-For: 62.103.214.39, 172.31.19.159
-   VCL_call       RECV
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 42221069 pass
-   Storage        malloc Transient
-   Timestamp      ReqBody: 1553163507.952175 0.819536 0.819536
-   Timestamp      Fetch: 1553163507.952297 0.819659 0.000123
-   RespProtocol   HTTP/1.1
-   RespStatus     503
-   RespReason     Backend fetch failed
-   RespHeader     Date: Thu, 21 Mar 2019 10:18:27 GMT
-   RespHeader     Server: Varnish
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   RespHeader     X-Varnish: 42221068
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/5.2)
-   VCL_call       DELIVER
-   RespUnset      Age: 0
-   RespUnset      Server: Varnish
-   RespUnset      X-Varnish: 42221068
-   RespUnset      Via: 1.1 varnish (Varnish/5.2)
-   VCL_return     deliver
-   Timestamp      Process: 1553163507.952322 0.819683 0.000024
-   RespHeader     Content-Length: 285
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1553163507.952341 0.819703 0.000020
-   ReqAcct        415 53 468 194 285 479
-   End            
**  << BeReq    >> 42221069  
--  Begin          bereq 42221068 pass
--  Timestamp      Start: 1553163507.132720 0.000000 0.000000
--  BereqMethod    POST
--  BereqURL       /path/to/request
--  BereqProtocol  HTTP/1.1
--  BereqHeader    X-Forwarded-Proto: https
--  BereqHeader    X-Forwarded-Port: 443
--  BereqHeader    Host: server.com
--  BereqHeader    X-Amzn-Trace-Id: Root=1-5c9364f3-26a603e3ce2f87d9923ed27e
--  BereqHeader    Content-Length: 53
--  BereqHeader    Accept: application/json
--  BereqHeader    Authorization: Bearer 3pa8ot18dlmpad2s34a5gt3p08jg0ml5
--  BereqHeader    Content-Type: application/json; charset=utf-8
--  BereqHeader    Cookie: PHPSESSID=o1f3010cuch8iu055stl6q1s03
--  BereqHeader    X-Forwarded-For: 62.103.214.39, 172.31.19.159
--  BereqHeader    X-Varnish: 42221069
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  BackendOpen    32 reload_20190304_175528_18074.live1 172.31.11.111 8081 172.31.31.198 39914
--  BackendStart   172.31.11.111 8081
--  Timestamp      Bereq: 1553163507.952205 0.819485 0.819485
--  FetchError     HTC status -1
--  BackendClose   32 reload_20190304_175528_18074.live1
--  Timestamp      Beresp: 1553163507.952235 0.819514 0.000029
--  Timestamp      Error: 1553163507.952237 0.819517 0.000003
--  BerespProtocol HTTP/1.1
--  BerespStatus   503
--  BerespReason   Service Unavailable
--  BerespReason   Backend fetch failed
--  BerespHeader   Date: Thu, 21 Mar 2019 10:18:27 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, 21 Mar 2019 10:18:27 GMT
--  ObjHeader      Server: Varnish
--  ObjHeader      Content-Type: text/html; charset=utf-8
--  ObjHeader      Retry-After: 5
--  Length         285
--  BereqAcct      451 53 504 0 0 0
--  End       

From what we understand, Varnish is reporting a connection closed (EOF) from Apache but again Apache is not reporting anything on it's side.

We need to somehow get to the bottom of this as it is effecting service agreement.

Any ideas on tracing and solving the problem?

Answer 1

You don't have an Apache access log because the request is not fully handled by Apache as there is a problem before.

This kind of problem could lead to this situation:

• network issue
• Apache error, like too many requests, invalid request or some internal error
• System error, like too many open files for the Apache user

Where you can look for traces:

• Apache error log
• System error log
• Run a tcpdump (tshark/wireshark are good tools for this) and look for errors