varnish Error 503 Backend fetch failed only on web app delivered via nginx (varnishlog attached) - Docker

Sam
April 28, 2022
92 views
0 votes
2 Answers

I want to cache two applications with varnish. One is a static Vue app and the second app is a Go REST API server. All runs on docker swarm and the API is responding fine, but when I query the Vue container via varnish, then I get the 503 Backend fetch failed error.

Both apps can be accessed directly on the server via http://ip:8080 and http://ip:3000/api/... but as mentioned the static web app does not respond (port=8080).

I know that varnish reponds that the default is unhealthy, but I do not know why, because it is accessible and I added a timeout etc in the default.vcl (see below).

I ran the log to get the error:

$ docker exec -it ... varnishlog -g raw -i backend_health
         0 Backend_health - default Still sick -------- 0 3 5 0.000000 0.000000 "Open error 110 (Connection timed out)"

Suspicion

The only suspicion I have, is that the URL redirect in the nginx container for the Vue application is redirecting the request in a way that the .probe does not work. This is the nginx.conf of the Vue app:

server {
    listen          80;
    server_name     _ default_server;
    index           index.html;

    location / {
        root        /usr/share/nginx/html;
        index       index.html;
        try_files   $uri $uri/ /index.html;
    }
}

Files

This is the docker-compose.yml file (I only addded host.docker.internal for testing, nothing changes when I use different addresses, like: client, the server IP or host.docker.internal as host in the default.vcl.

version: '3.9'
services:
  server:
    image: ...
    ports:
      - target: 3000
        published: 3000
        mode: host
    networks:
      - web
      - db-net
    depends_on:
      - db
    command: [ "./wait-for-it.sh", "db:5432", "--", "./streamsink" ]
    deploy:
      mode: replicated
      replicas: 1
      restart_policy:
        condition: on-failure
        delay: 10s
        max_attempts: 10
        window: 120s
      placement:
        constraints:
          - node.role == manager
    client:
        image: ...
        extra_hosts:
          - "host.docker.internal:host-gateway"
        ports:
          - target: 80
            published: 8080
            mode: host
        depends_on:
          - server
        networks:
          - web
        deploy:
          restart_policy:
            condition: on-failure

  varnish:
    image: varnish:latest
    extra_hosts:
      - "host.docker.internal:host-gateway"
    ports:
      - target: 80
        published: 80
        mode: host
    environment:
      - VARNISH_SIZE=2G
    tmpfs:
      - /var/lib/varnish/varnishd:exec
    volumes:
      - ./default.vcl:/etc/varnish/default.vcl:ro
    networks:
      - web
    depends_on:
      - client
      - server
    deploy:
      mode: replicated
      replicas: 1
      restart_policy:
        condition: on-failure
      placement:
        constraints:
          - node.role == manager

    ...

    networks:
      web:
        external: true
      db-net:
        external: true

This is the default.vcl file

vcl 4.1;

# import vmod_dynamic for better backend name resolution
import dynamic;

# we won't use any static backend, but Varnish still need a default one
backend default {
    .host = "host.docker.internal";
    .port = "8080";
    .connect_timeout = 600s;
    .first_byte_timeout = 600s;
    .between_bytes_timeout = 600s;
    .probe = {
        .url = "/";
        .interval = 5s;
        .timeout = 50s;
        .window = 5;
        .threshold = 3;
    }
}

backend api {
    .host = "host.docker.internal";
    .port = "3000";
}

sub vcl_backend_response {
  set beresp.ttl = 12h;
}

sub vcl_recv {
    if (req.url ~ "^/api/") {
        set req.backend_hint = api;
    }
    else {
        set req.backend_hint = default;
    }
}

This is the log from the request on the Varnish server:

*   << Request  >> 46        
-   Begin          req 45 rxreq
-   Timestamp      Start: 1651165979.997021 0.000000 0.000000
-   Timestamp      Req: 1651165979.997021 0.000000 0.000000
-   VCL_use        boot
-   ReqStart       172.20.0.1 59730 http
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: 192.168.0.123
-   ReqHeader      Connection: keep-alive
-   ReqHeader      Cache-Control: max-age=0
-   ReqHeader      DNT: 1
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36
-   ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
-   ReqHeader      Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
-   ReqHeader      sec-gpc: 1
-   ReqHeader      X-Forwarded-For: 172.20.0.1
-   VCL_call       RECV
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 47 pass
-   Timestamp      Fetch: 1651165979.997170 0.000149 0.000149
-   RespProtocol   HTTP/1.1
-   RespStatus     503
-   RespReason     Backend fetch failed
-   RespHeader     Date: Thu, 28 Apr 2022 17:12:59 GMT
-   RespHeader     Server: Varnish
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   RespHeader     X-Varnish: 46
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/7.1)
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1651165979.997182 0.000161 0.000011
-   Filters        
-   RespHeader     Content-Length: 279
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1651165979.997244 0.000222 0.000061
-   ReqAcct        528 0 528 247 279 526
-   End            
**  << BeReq    >> 47        
--  Begin          bereq 46 pass
--  VCL_use        boot
--  Timestamp      Start: 1651165979.997101 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /
--  BereqProtocol  HTTP/1.1
--  BereqHeader    Host: 192.168.0.123
--  BereqHeader    Cache-Control: max-age=0
--  BereqHeader    DNT: 1
--  BereqHeader    Upgrade-Insecure-Requests: 1
--  BereqHeader    User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36
--  BereqHeader    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
--  BereqHeader    Accept-Encoding: gzip, deflate
--  BereqHeader    Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
--  BereqHeader    sec-gpc: 1
--  BereqHeader    X-Forwarded-For: 172.20.0.1
--  BereqHeader    X-Varnish: 47
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  Timestamp      Fetch: 1651165979.997116 0.000015 0.000015
--  FetchError     backend default: unhealthy
--  Timestamp      Beresp: 1651165979.997121 0.000020 0.000005
--  Timestamp      Error: 1651165979.997123 0.000022 0.000002
--  BerespProtocol HTTP/1.1
--  BerespStatus   503
--  BerespReason   Backend fetch failed
--  BerespHeader   Date: Thu, 28 Apr 2022 17:12:59 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
--  Length         279
--  BereqAcct      0 0 0 0 0 0
--  End            

*   << Request  >> 48        
-   Begin          req 45 rxreq
-   Timestamp      Start: 1651165980.087213 0.000000 0.000000
-   Timestamp      Req: 1651165980.087213 0.000000 0.000000
-   VCL_use        boot
-   ReqStart       172.20.0.1 59730 http
-   ReqMethod      GET
-   ReqURL         /favicon.ico
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: 192.168.0.123
-   ReqHeader      Connection: keep-alive
-   ReqHeader      User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36
-   ReqHeader      DNT: 1
-   ReqHeader      Accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
-   ReqHeader      Referer: http://192.168.0.123/
-   ReqHeader      Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
-   ReqHeader      sec-gpc: 1
-   ReqHeader      X-Forwarded-For: 172.20.0.1
-   VCL_call       RECV
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 49 pass
-   Timestamp      Fetch: 1651165980.087367 0.000153 0.000153
-   RespProtocol   HTTP/1.1
-   RespStatus     503
-   RespReason     Backend fetch failed
-   RespHeader     Date: Thu, 28 Apr 2022 17:13:00 GMT
-   RespHeader     Server: Varnish
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   RespHeader     X-Varnish: 48
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/7.1)
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1651165980.087382 0.000168 0.000014
-   Filters        
-   RespHeader     Content-Length: 279
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1651165980.087445 0.000231 0.000063
-   ReqAcct        443 0 443 247 279 526
-   End            
**  << BeReq    >> 49        
--  Begin          bereq 48 pass
--  VCL_use        boot
--  Timestamp      Start: 1651165980.087307 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /favicon.ico
--  BereqProtocol  HTTP/1.1
--  BereqHeader    Host: 192.168.0.123
--  BereqHeader    User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36
--  BereqHeader    DNT: 1
--  BereqHeader    Accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
--  BereqHeader    Referer: http://192.168.0.123/
--  BereqHeader    Accept-Encoding: gzip, deflate
--  BereqHeader    Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
--  BereqHeader    sec-gpc: 1
--  BereqHeader    X-Forwarded-For: 172.20.0.1
--  BereqHeader    X-Varnish: 49
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  Timestamp      Fetch: 1651165980.087327 0.000019 0.000019
--  FetchError     backend default: unhealthy
--  Timestamp      Beresp: 1651165980.087332 0.000025 0.000005
--  Timestamp      Error: 1651165980.087334 0.000027 0.000002
--  BerespProtocol HTTP/1.1
--  BerespStatus   503
--  BerespReason   Backend fetch failed
--  BerespHeader   Date: Thu, 28 Apr 2022 17:13:00 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
--  Length         279
--  BereqAcct      0 0 0 0 0 0
--  End

Answers

Chosen as BEST ANSWER
- Sam
- April 28, 2022 at 11:28 pm
- 0 votes
0
The solution is rather weird. I just had to remove the ports: section in the docker compose and use the service name in the default.vcl file.

compose:
```
client:
    image: ...
    ports: <-- remove
      - target: 80
        published: 8080
        mode: host
```
Access straight the internal port in the default.vcl
```
backend default {
    .host = "client";
    .port = "80";
}
```
This might have something to do with docker swarm. I don't know why.

(Edit)

- ThijsFeryn
- April 28, 2022 at 8:28 pm
- 0 votes
0
```
Open error 110 (Connection timed out)
```
Try accessing the Varnish container through a bash shell, as illustrated below:
```
docker exec -ti varnish bash
```
Assuming that name of your Varnish container is varnish

Run the following commands to install some debugging dependencies:
```
apt-get update
apt-get install -y telnet curl dnsutils
```
Then run the following debugging commands:
```
dig host.docker.internal
telnet host.docker.internal 8080
curl http://host.docker.internal:8080
```
1. The 1st command will check if host.docker.internal resolves to an IP address
2. The 2nd command will check if host host.docker.internal listens for incoming connections on port 8080
3. The 3rd command will try an HTTP request on http://host.docker.internal:8080
Keep in mind that Varnish can only connect with backends over plain HTTP. HTTPS backends are not supported.

Depending on the results of these debugging commands, you should know what’s going on, whether or not the service is reachable and if the backend responds in a timely fashion.
Login or Signup to reply.

Please signup or login to give your own answer.

Click here to cancel reply.

varnish Error 503 Backend fetch failed only on web app delivered via nginx (varnishlog attached) – Docker

Answers