3

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
  1. 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;
    }
}
  1. I also tried removing Magento's health check probe as per this answer
3

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.

| improve this answer | |
  • Thanks, this helped. The error I'm seeing is straight insufficient bytes which I understand means an incorrect Content-Length. However it's strange; I can't immediately understand why the content length would be incorrect. I checked Apache logs for a problem file; I noticed it was served (200 OK) with a length of 42149 bytes, then two minutes later (in a separate request) the same file was served (200 OK) at 11390 bytes. Both these requests went through Varnish return(pass), but on the second request I saw the error. Changing pass to pipe solves the problem - any ideas why? – WackGet Jul 10 at 4:43
  • Also, removing the return completely (i.e. trying to let Varnish cache the files) makes the problem come back. Only return(pipe) seems to solve the issue. It's almost as if Apache is trying to "stream" these files in chunks to the browser (like a streaming video, which I understand only works with pipe?) because these files do take 6-7 seconds each to be served by Apache (Magento 2 dev mode is stupidly slow). Is Apache trying to send only part of a response for some reason and Varnish doesn't wait for it to send the rest? Does that sound at all plausible? – WackGet Jul 10 at 4:51
  • Varnish does support Chunked Transfer Encoding for streaming. return(pipe) should only be used when you notice the response is not pure HTTP. (e.g. a websocket upgrade). Please share the full Varnishlog and I'll try to figure out what's going on. – Thijs Feryn Jul 13 at 6:38

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.