How do I properly debug the root cause of 503 errors produced by Varnish?

Question

I'm using Magento 2.3.5 with Apache 2.4 and Varnish 6 and seeing constant 503 errors ("Backend Fetch Failed" or sometimes "Service Unavailable") in the browser's network panel when page assets are loading.

The 503 errors don't affect all requests; on a typical page load in developer mode, when a Magento page might require about 200 external assets (JS/CSS/template files etc.) about 80-90% of requests are successful but 10-20% are not.

The errors do not always affect the same files; it is quite random although anecdotally I would say that larger files are affected moreso than tiny files.

If I manually request the problem URL in the browser, or click Resend in the browser's network panel to retry the request, the request almost always succeeds with a 200 OK response straight away.

In this way, I am usually able to load a page fully without any 503 errors by a process of refreshing the page 4, 5, or 6 times until all the 503 are "exhausted" and "turn into" 200 OK responses.

Obviously this is not OK, and something is wrong; pages should load first time every time.

Debugging

I have debugged extensively trying to find the root cause of this. Things I have tried:

1. varnishlog output is not particularly helpful. It simply states that the backend fetch failed without saying why (e.g. did it time out? etc.)

    > -   VCL_return     pass
    > -   VCL_call       HASH
    > -   VCL_return     lookup
    > -   VCL_call       PASS
    > -   VCL_return     fetch
    > -   Link           bereq 720946 pass
    > -   Timestamp      Fetch: 1593622218.746588 0.461734 0.461734
    > -   RespProtocol   HTTP/1.1
    > -   RespStatus     503
    > -   RespReason     Backend fetch failed

2. I've tried increasing the first byte and connect timeouts in Varnish as per the VCL configuration below:

VCL Configuration

backend default {
    .host = "localhost";
    .host_header = "mysite.example.com";
    .port = "8080";
    .connect_timeout = 600s;
    .first_byte_timeout = 600s;
    .probe = {
         .url = "/pub/health_check.php";
         .timeout = 2s;
         .interval = 5s;
         .window = 10;
         .threshold = 5;
    }
}

3. I also tried removing Magento's health check probe as per this answer

Answer 1

It's a good idea to look at the varnishlog output. You pasted client-side varnishlog output, but the reason why fetches fail is reported in the backend-side varnishlog output.

The part where the backend request happens will have a FetchError tag, that will tell you what was going on.

Looking for fetch errors

Here's an example where I reached the backend's connection timeout:

FetchError     backend boot.default: fail errno 110 (Connection timed out)

Here's an example where I reached the backend's first byte timeout:

FetchError     HTC idle (3)

It could also be that your health probe already detected that the backend was unhealthy. Then you'll get the following output:

FetchError     backend boot.default: unhealthy

In that case, it's a matter of looking at the backend_health tag, that is not part of your request transaction log. The next section describes how to do this.

Monitor health probes

Because you defined a probe, you can even check the backend's health without sending requests to Varnish. Just run the following varnishlog command:

varnishlog -g raw -i backend_health

With your current probe settings, this is the output you can get when all of the sudden, the backend goes down:

0 Backend_health - boot.default Still healthy 4---X-RH 10 5 10 0.007322 0.008134 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy -------- 9 5 10 0.000000 0.008378 Open error 110 (Connection timed out)
0 Backend_health - boot.default Still healthy -------- 8 5 10 0.000000 0.008378 Open error 110 (Connection timed out)
0 Backend_health - boot.default Still healthy -------- 7 5 10 0.000000 0.008378 Open error 110 (Connection timed out)
0 Backend_health - boot.default Still healthy -------- 6 5 10 0.000000 0.008378 Open error 110 (Connection timed out)
0 Backend_health - boot.default Still healthy -------- 5 5 10 0.000000 0.008378 Open error 113 (No route to host)
0 Backend_health - boot.default Went sick -------- 4 5 10 0.000000 0.008378 Open error 113 (No route to host)
0 Backend_health - boot.default Still sick -------- 3 5 10 0.000000 0.008378 Open error 113 (No route to host)

Your probe treshold is set to 5, you probe window is 10, and the probing interval is 5 seconds. This means that every 5 seconds is check is done. If 5 out of 10 checks fail, the backend will be considered sick.

Here's an example of first byte timeout issues while polling:

0 Backend_health - boot.default Still healthy 4---X-RH 8 5 10 0.007883 0.007988 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---X-RH 9 5 10 0.006643 0.007651 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---X-RH 10 5 10 0.009310 0.008066 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---X-RH 10 5 10 0.007814 0.008003 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---Xr-- 9 5 10 0.000000 0.008003 Poll error 0 (Success)
0 Backend_health - boot.default Still healthy 4---Xr-- 8 5 10 0.000000 0.008003 Poll error 0 (Success)
0 Backend_health - boot.default Still healthy 4---Xr-- 7 5 10 0.000000 0.008003 Poll error 0 (Success)
0 Backend_health - boot.default Still healthy 4---Xr-- 6 5 10 0.000000 0.008003 Poll error 0 (Success)
0 Backend_health - boot.default Still healthy 4---X-RH 6 5 10 1.008046 0.258014 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---X-RH 6 5 10 1.009443 0.445871 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---Xr-- 5 5 10 0.000000 0.445871 Poll error 0 (Success)
0 Backend_health - boot.default Went sick 4---Xr-- 4 5 10 0.000000 0.445871 Poll error 0 (Success)
0 Backend_health - boot.default Still sick 4---Xr-- 3 5 10 0.000000 0.445871 Poll error 0 (Success)

And finally, here's an example of a backend returning an HTTP/1.1 500 error:

0 Backend_health - boot.default Still healthy 4---X-RH 8 5 10 0.007650 0.051617 HTTP/1.1 200 OK
0 Backend_health - boot.default Still healthy 4---X-R- 8 5 10 0.007428 0.051617 HTTP/1.1 500 Internal Server Error
0 Backend_health - boot.default Still healthy 4---X-R- 7 5 10 0.006010 0.051617 HTTP/1.1 500 Internal Server Error
0 Backend_health - boot.default Still healthy 4---X-R- 6 5 10 0.009069 0.051617 HTTP/1.1 500 Internal Server Error
0 Backend_health - boot.default Still healthy 4---X-R- 5 5 10 0.006412 0.051617 HTTP/1.1 500 Internal Server Error
0 Backend_health - boot.default Went sick 4---X-R- 4 5 10 0.008542 0.051617 HTTP/1.1 500 Internal Server Error
0 Backend_health - boot.default Still sick 4---X-R- 3 5 10 0.007250 0.051617 HTTP/1.1 500 Internal Server Error

Conclusion

You're definitely looking in the right direction using varnishlog, you just need to harness a bit more of its power to get the desired outcome.

Hope this helps.