I have a simple Express server running at https://img-optimizer-fragrant-cloud-4712.fly.dev and I would like to use Varnish to cache requests (both on fly.io).
The backend looks healthy (according to the probe results), but as soon as I send a request to Varnish, it returns "Error 503 Backend fetch failed".
Fetching from the backend works as expected: curl http://img-optimizer-fragrant-cloud-4712.fly.dev:80 (it returns a content-type of image/webp).
Here's my default.vcl:
vcl 4.1;
backend default {
.host = "img-optimizer-fragrant-cloud-4712.fly.dev";
.port = "80";
.probe = {
.url = "/";
.timeout = 5s;
.interval = 20s;
.window = 10;
.threshold = 3;
}
}
sub vcl_recv {
unset req.http.x-cache;
}
sub vcl_hit {
set req.http.x-cache = "hit";
}
sub vcl_miss {
set req.http.x-cache = "miss";
}
sub vcl_pass {
set req.http.x-cache = "pass";
}
sub vcl_pipe {
set req.http.x-cache = "pipe uncacheable";
}
sub vcl_synth {
set req.http.x-cache = "synth synth";
set resp.http.x-cache = req.http.x-cache;
}
sub vcl_deliver {
if (obj.uncacheable) {
set req.http.x-cache = req.http.x-cache + " uncacheable" ;
} else {
set req.http.x-cache = req.http.x-cache + " cached" ;
}
set resp.http.x-cache = req.http.x-cache;
}
And my Dockerfile:
# See https://til.simonwillison.net/fly/varnish-on-fly
FROM varnish
COPY default.vcl /etc/varnish/
USER varnish
ENTRYPOINT [ \
"varnishd", "-F", \
"-f", "/etc/varnish/default.vcl", \
"-a", "http=:8080,HTTP", \
"-s", "malloc,256M", \
"-T", "none" \
]
Calling varnishlog -g raw -i backend_health on the server returns a healthy backend: 0 Backend_health - default Still healthy 4---X-RH 10 3 10 0.227228 0.214281 "HTTP/1.1 200 OK"
However, fetching from Varnish (curl -v http://image-optimizer-varnish.fly.dev) returns:
< HTTP/1.1 503 Backend fetch failed
< date: Tue, 14 May 2024 14:40:15 GMT
< server: Fly/d5207058 (2024-05-13)
< content-type: text/html; charset=utf-8
< retry-after: 5
< x-varnish: 5
< age: 0
< via: 1.1 3287147dc7e085 (Varnish/7.5), 1.1 fly.io
< x-cache: misss cached
< content-length: 278
< connection: keep-alive
< fly-request-id: 01HXVRR0V652Q4174W4FAFN4CB-fra
<
<!DOCTYPE html>
<html>
<head>
<title>503 Backend fetch failed</title>
</head>
<body>
<h1>Error 503 Backend fetch failed</h1>
<p>Backend fetch failed</p>
<h3>Guru Meditation:</h3>
<p>XID: 6</p>
<hr>
<p>Varnish cache server</p>
</body>
</html>
Inspecting the request through varnishlog -v gives me:
varnishlog -v
* << BeReq >> 32774
- 32774 Begin b bereq 32773 fetch
- 32774 VCL_use b boot
- 32774 Timestamp b Start: 1715976122.825963 0.000000 0.000000
- 32774 BereqMethod b GET
- 32774 BereqURL b /
- 32774 BereqProtocol b HTTP/1.1
- 32774 BereqHeader b pragma: no-cache
- 32774 BereqHeader b sec-ch-ua: "Chromium";v="124", "Google Chrome";v="124", "Not-A.Brand";v="99"
- 32774 BereqHeader b sec-ch-ua-mobile: ?0
- 32774 BereqHeader b sec-ch-ua-platform: "macOS"
- 32774 BereqHeader b dnt: 1
- 32774 BereqHeader b x-request-start: t=1715976122809682
- 32774 BereqHeader b user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
- 32774 BereqHeader b 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.7
- 32774 BereqHeader b sec-fetch-site: none
- 32774 BereqHeader b sec-fetch-mode: navigate
- 32774 BereqHeader b sec-fetch-user: ?1
- 32774 BereqHeader b sec-fetch-dest: document
- 32774 BereqHeader b accept-language: en-US,en;q=0.9,de-CH;q=0.8,de;q=0.7,fr;q=0.6
- 32774 BereqHeader b priority: u=0, i
- 32774 BereqHeader b host: image-optimizer-varnish.fly.dev
- 32774 BereqHeader b fly-client-ip: 83.150.5.242
- 32774 BereqHeader b fly-forwarded-proto: https
- 32774 BereqHeader b x-forwarded-proto: https
- 32774 BereqHeader b fly-forwarded-ssl: on
- 32774 BereqHeader b x-forwarded-ssl: on
- 32774 BereqHeader b fly-forwarded-port: 443
- 32774 BereqHeader b x-forwarded-port: 443
- 32774 BereqHeader b fly-region: fra
- 32774 BereqHeader b fly-request-id: 01HY42BCDSC16K3TD50YJY5EGH-fra
- 32774 BereqHeader b fly-traceparent: 00-b72ca569a24131cc7ba7f2bb22abecf2-6e8c489b5b7428c0-00
- 32774 BereqHeader b fly-tracestate:
- 32774 BereqHeader b X-Forwarded-For: 83.150.5.242, 66.241.124.150, 172.16.7.202
- 32774 BereqHeader b Via: 2 fly.io, 1.1 3287147dc7e085 (Varnish/7.5)
- 32774 BereqHeader b Accept-Encoding: gzip
- 32774 BereqHeader b x-cache: miss
- 32774 BereqHeader b X-Varnish: 32774
- 32774 VCL_call b BACKEND_FETCH
- 32774 VCL_return b fetch
- 32774 Timestamp b Fetch: 1715976122.825978 0.000015 0.000015
- 32774 Timestamp b Connected: 1715976122.826145 0.000182 0.000167
- 32774 BackendOpen b 22 default 66.241.124.229 80 172.19.7.202 37422 connect
- 32774 Timestamp b Bereq: 1715976122.826215 0.000251 0.000069
- 32774 FetchError b HTC eof (Unexpected end of input)
- 32774 BackendClose b 22 default close RX_BAD
- 32774 Timestamp b Beresp: 1715976122.826340 0.000376 0.000124
- 32774 Timestamp b Error: 1715976122.826340 0.000377 0.000000
- 32774 BerespProtocol b HTTP/1.1
- 32774 BerespStatus b 503
- 32774 BerespReason b Backend fetch failed
- 32774 BerespHeader b Date: Fri, 17 May 2024 20:02:02 GMT
- 32774 BerespHeader b Server: Varnish
- 32774 VCL_call b BACKEND_ERROR
- 32774 BerespHeader b Content-Type: text/html; charset=utf-8
- 32774 BerespHeader b Retry-After: 5
- 32774 VCL_return b deliver
- 32774 Storage b malloc Transient
- 32774 Length b 282
- 32774 BereqAcct b 1197 0 1197 0 0 0
- 32774 End b
* << Request >> 32773
- 32773 Begin c req 32772 rxreq
- 32773 Timestamp c Start: 1715976122.825851 0.000000 0.000000
- 32773 Timestamp c Req: 1715976122.825851 0.000000 0.000000
- 32773 VCL_use c boot
- 32773 ReqStart c 172.16.7.202 43330 http
- 32773 ReqMethod c GET
- 32773 ReqURL c /
- 32773 ReqProtocol c HTTP/1.1
- 32773 ReqHeader c pragma: no-cache
- 32773 ReqHeader c cache-control: no-cache
- 32773 ReqHeader c sec-ch-ua: "Chromium";v="124", "Google Chrome";v="124", "Not-A.Brand";v="99"
- 32773 ReqHeader c sec-ch-ua-mobile: ?0
- 32773 ReqHeader c sec-ch-ua-platform: "macOS"
- 32773 ReqHeader c dnt: 1
- 32773 ReqHeader c x-request-start: t=1715976122809682
- 32773 ReqHeader c user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
- 32773 ReqHeader c 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.7
- 32773 ReqHeader c sec-fetch-site: none
- 32773 ReqHeader c sec-fetch-mode: navigate
- 32773 ReqHeader c sec-fetch-user: ?1
- 32773 ReqHeader c sec-fetch-dest: document
- 32773 ReqHeader c accept-encoding: gzip, deflate, br, zstd
- 32773 ReqHeader c accept-language: en-US,en;q=0.9,de-CH;q=0.8,de;q=0.7,fr;q=0.6
- 32773 ReqHeader c priority: u=0, i
- 32773 ReqHeader c host: image-optimizer-varnish.fly.dev
- 32773 ReqHeader c fly-client-ip: 83.150.5.242
- 32773 ReqHeader c x-forwarded-for: 83.150.5.242, 66.241.124.150
- 32773 ReqHeader c fly-forwarded-proto: https
- 32773 ReqHeader c x-forwarded-proto: https
- 32773 ReqHeader c fly-forwarded-ssl: on
- 32773 ReqHeader c x-forwarded-ssl: on
- 32773 ReqHeader c fly-forwarded-port: 443
- 32773 ReqHeader c x-forwarded-port: 443
- 32773 ReqHeader c fly-region: fra
- 32773 ReqHeader c fly-request-id: 01HY42BCDSC16K3TD50YJY5EGH-fra
- 32773 ReqHeader c via: 2 fly.io
- 32773 ReqHeader c fly-traceparent: 00-b72ca569a24131cc7ba7f2bb22abecf2-6e8c489b5b7428c0-00
- 32773 ReqHeader c fly-tracestate:
- 32773 ReqUnset c x-forwarded-for: 83.150.5.242, 66.241.124.150
- 32773 ReqHeader c X-Forwarded-For: 83.150.5.242, 66.241.124.150, 172.16.7.202
- 32773 ReqUnset c via: 2 fly.io
- 32773 ReqHeader c Via: 2 fly.io, 1.1 3287147dc7e085 (Varnish/7.5)
- 32773 VCL_call c RECV
- 32773 VCL_return c hash
- 32773 ReqUnset c accept-encoding: gzip, deflate, br, zstd
- 32773 ReqHeader c Accept-Encoding: gzip
- 32773 VCL_call c HASH
- 32773 VCL_return c lookup
- 32773 VCL_call c MISS
- 32773 ReqHeader c x-cache: miss
- 32773 VCL_return c fetch
- 32773 Link c bereq 32774 fetch
- 32773 Timestamp c Fetch: 1715976122.826399 0.000548 0.000548
- 32773 RespProtocol c HTTP/1.1
- 32773 RespStatus c 503
- 32773 RespReason c Backend fetch failed
- 32773 RespHeader c Date: Fri, 17 May 2024 20:02:02 GMT
- 32773 RespHeader c Server: Varnish
- 32773 RespHeader c Content-Type: text/html; charset=utf-8
- 32773 RespHeader c Retry-After: 5
- 32773 RespHeader c X-Varnish: 32773
- 32773 RespHeader c Age: 0
- 32773 RespHeader c Via: 1.1 3287147dc7e085 (Varnish/7.5)
- 32773 VCL_call c DELIVER
- 32773 ReqUnset c x-cache: miss
- 32773 ReqHeader c x-cache: miss cached
- 32773 RespHeader c x-cache: miss cached
- 32773 VCL_return c deliver
- 32773 Timestamp c Process: 1715976122.826412 0.000560 0.000012
- 32773 Filters c
- 32773 RespHeader c Content-Length: 282
- 32773 RespHeader c Connection: keep-alive
- 32773 Timestamp c Resp: 1715976122.826436 0.000584 0.000024
- 32773 ReqAcct c 1161 0 1161 279 282 561
- 32773 End c
* << Session >> 32772
- 32772 Begin c sess 0 HTTP/1
- 32772 SessOpen c 172.16.7.202 43330 http 172.19.7.202 8080 1715976122.825804 20
- 32772 Link c req 32773 rxreq
- 32772 SessClose c REM_CLOSE 0.001
- 32772 End c
* << BeReq >> 9
- 9 Begin b bereq 8 fetch
- 9 VCL_use b boot
- 9 Timestamp b Start: 1715976122.921363 0.000000 0.000000
- 9 BereqMethod b GET
- 9 BereqURL b /favicon.ico
- 9 BereqProtocol b HTTP/1.1
- 9 BereqHeader b pragma: no-cache
- 9 BereqHeader b sec-ch-ua: "Chromium";v="124", "Google Chrome";v="124", "Not-A.Brand";v="99"
- 9 BereqHeader b dnt: 1
- 9 BereqHeader b sec-ch-ua-mobile: ?0
- 9 BereqHeader b user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
- 9 BereqHeader b sec-ch-ua-platform: "macOS"
- 9 BereqHeader b accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
- 9 BereqHeader b sec-fetch-site: same-origin
- 9 BereqHeader b sec-fetch-mode: no-cors
- 9 BereqHeader b sec-fetch-dest: image
- 9 BereqHeader b referer: https://image-optimizer-varnish.fly.dev/
- 9 BereqHeader b accept-language: en-US,en;q=0.9,de-CH;q=0.8,de;q=0.7,fr;q=0.6
- 9 BereqHeader b priority: u=1, i
- 9 BereqHeader b x-request-start: t=1715976122915192
- 9 BereqHeader b host: image-optimizer-varnish.fly.dev
- 9 BereqHeader b fly-client-ip: 83.150.5.242
- 9 BereqHeader b fly-forwarded-proto: https
- 9 BereqHeader b x-forwarded-proto: https
- 9 BereqHeader b fly-forwarded-ssl: on
- 9 BereqHeader b x-forwarded-ssl: on
- 9 BereqHeader b fly-forwarded-port: 443
- 9 BereqHeader b x-forwarded-port: 443
- 9 BereqHeader b fly-region: fra
- 9 BereqHeader b fly-request-id: 01HY42BCH35QFJ7Y0R3KRTPYK9-fra
- 9 BereqHeader b fly-traceparent: 00-0d7d3240e34d50be2f68e4fdfcaeb9e6-0cf2586ae1b6da4b-00
- 9 BereqHeader b fly-tracestate:
- 9 BereqHeader b X-Forwarded-For: 83.150.5.242, 66.241.124.150, 172.16.7.202
- 9 BereqHeader b Via: 2 fly.io, 1.1 3287147dc7e085 (Varnish/7.5)
- 9 BereqHeader b Accept-Encoding: gzip
- 9 BereqHeader b x-cache: miss
- 9 BereqHeader b X-Varnish: 9
- 9 VCL_call b BACKEND_FETCH
- 9 VCL_return b fetch
- 9 Timestamp b Fetch: 1715976122.921375 0.000012 0.000012
- 9 Timestamp b Connected: 1715976122.921518 0.000155 0.000142
- 9 BackendOpen b 22 default 66.241.124.229 80 172.19.7.202 37426 connect
- 9 Timestamp b Bereq: 1715976122.921547 0.000184 0.000029
- 9 FetchError b HTC eof (Unexpected end of input)
- 9 BackendClose b 22 default close RX_BAD
- 9 Timestamp b Beresp: 1715976122.921739 0.000376 0.000192
- 9 Timestamp b Error: 1715976122.921740 0.000377 0.000001
- 9 BerespProtocol b HTTP/1.1
- 9 BerespStatus b 503
- 9 BerespReason b Backend fetch failed
- 9 BerespHeader b Date: Fri, 17 May 2024 20:02:02 GMT
- 9 BerespHeader b Server: Varnish
- 9 VCL_call b BACKEND_ERROR
- 9 BerespHeader b Content-Type: text/html; charset=utf-8
- 9 BerespHeader b Retry-After: 5
- 9 VCL_return b deliver
- 9 Storage b malloc Transient
- 9 Length b 278
- 9 BereqAcct b 1167 0 1167 0 0 0
- 9 End b
* << Request >> 8
- 8 Begin c req 7 rxreq
- 8 Timestamp c Start: 1715976122.921303 0.000000 0.000000
- 8 Timestamp c Req: 1715976122.921303 0.000000 0.000000
- 8 VCL_use c boot
- 8 ReqStart c 172.16.7.202 43342 http
- 8 ReqMethod c GET
- 8 ReqURL c /favicon.ico
- 8 ReqProtocol c HTTP/1.1
- 8 ReqHeader c pragma: no-cache
- 8 ReqHeader c cache-control: no-cache
- 8 ReqHeader c sec-ch-ua: "Chromium";v="124", "Google Chrome";v="124", "Not-A.Brand";v="99"
- 8 ReqHeader c dnt: 1
- 8 ReqHeader c sec-ch-ua-mobile: ?0
- 8 ReqHeader c user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36
- 8 ReqHeader c sec-ch-ua-platform: "macOS"
- 8 ReqHeader c accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
- 8 ReqHeader c sec-fetch-site: same-origin
- 8 ReqHeader c sec-fetch-mode: no-cors
- 8 ReqHeader c sec-fetch-dest: image
- 8 ReqHeader c referer: https://image-optimizer-varnish.fly.dev/
- 8 ReqHeader c accept-encoding: gzip, deflate, br, zstd
- 8 ReqHeader c accept-language: en-US,en;q=0.9,de-CH;q=0.8,de;q=0.7,fr;q=0.6
- 8 ReqHeader c priority: u=1, i
- 8 ReqHeader c x-request-start: t=1715976122915192
- 8 ReqHeader c host: image-optimizer-varnish.fly.dev
- 8 ReqHeader c fly-client-ip: 83.150.5.242
- 8 ReqHeader c x-forwarded-for: 83.150.5.242, 66.241.124.150
- 8 ReqHeader c fly-forwarded-proto: https
- 8 ReqHeader c x-forwarded-proto: https
- 8 ReqHeader c fly-forwarded-ssl: on
- 8 ReqHeader c x-forwarded-ssl: on
- 8 ReqHeader c fly-forwarded-port: 443
- 8 ReqHeader c x-forwarded-port: 443
- 8 ReqHeader c fly-region: fra
- 8 ReqHeader c fly-request-id: 01HY42BCH35QFJ7Y0R3KRTPYK9-fra
- 8 ReqHeader c via: 2 fly.io
- 8 ReqHeader c fly-traceparent: 00-0d7d3240e34d50be2f68e4fdfcaeb9e6-0cf2586ae1b6da4b-00
- 8 ReqHeader c fly-tracestate:
- 8 ReqUnset c x-forwarded-for: 83.150.5.242, 66.241.124.150
- 8 ReqHeader c X-Forwarded-For: 83.150.5.242, 66.241.124.150, 172.16.7.202
- 8 ReqUnset c via: 2 fly.io
- 8 ReqHeader c Via: 2 fly.io, 1.1 3287147dc7e085 (Varnish/7.5)
- 8 VCL_call c RECV
- 8 VCL_return c hash
- 8 ReqUnset c accept-encoding: gzip, deflate, br, zstd
- 8 ReqHeader c Accept-Encoding: gzip
- 8 VCL_call c HASH
- 8 VCL_return c lookup
- 8 VCL_call c MISS
- 8 ReqHeader c x-cache: miss
- 8 VCL_return c fetch
- 8 Link c bereq 9 fetch
- 8 Timestamp c Fetch: 1715976122.921805 0.000501 0.000501
- 8 RespProtocol c HTTP/1.1
- 8 RespStatus c 503
- 8 RespReason c Backend fetch failed
- 8 RespHeader c Date: Fri, 17 May 2024 20:02:02 GMT
- 8 RespHeader c Server: Varnish
- 8 RespHeader c Content-Type: text/html; charset=utf-8
- 8 RespHeader c Retry-After: 5
- 8 RespHeader c X-Varnish: 8
- 8 RespHeader c Age: 0
- 8 RespHeader c Via: 1.1 3287147dc7e085 (Varnish/7.5)
- 8 VCL_call c DELIVER
- 8 ReqUnset c x-cache: miss
- 8 ReqHeader c x-cache: miss cached
- 8 RespHeader c x-cache: miss cached
- 8 VCL_return c deliver
- 8 Timestamp c Process: 1715976122.921813 0.000509 0.000008
- 8 Filters c
- 8 RespHeader c Content-Length: 278
- 8 RespHeader c Connection: keep-alive
- 8 Timestamp c Resp: 1715976122.921834 0.000530 0.000020
- 8 ReqAcct c 1135 0 1135 275 278 553
- 8 End c
* << Session >> 7
- 7 Begin c sess 0 HTTP/1
- 7 SessOpen c 172.16.7.202 43342 http 172.19.7.202 8080 1715976122.921239 19
- 7 Link c req 8 rxreq
- 7 SessClose c REM_CLOSE 0.001
- 7 End c
I don't think that timeouts are a problem, given that I'm using the same endpoint to probe and fetch data, because it usually responds with less than 1s and adding the following lines to the backend didn't help:
.first_byte_timeout = 120s;
.connect_timeout = 60s;
.between_bytes_timeout = 60s;
Any ideas why the probe does not match the real-world requests?
I ran your use case in a Docker container using the following VCL:
vcl 4.1;
backend default {
.host = "img-optimizer-fragrant-cloud-4712.fly.dev";
}
I received the same kind of error:
-- FetchError HTC eof (-1)
-- BackendClose 31 default close Received bad req/resp
This indicates that the backend doesn't even respond and closes the connection before sending any content.
However, when I add the right Host header, it does work.
Here's an example of a failed request:
$ curl -I localhost
HTTP/1.1 503 Backend fetch failed
Date: Sat, 18 May 2024 08:30:27 GMT
Server: Varnish
Content-Type: text/html; charset=utf-8
Retry-After: 5
X-Varnish: 32776
Age: 0
Via: 1.1 varnish (Varnish/7.3)
Content-Length: 282
Connection: keep-alive
Here's an example of a working request:
$ curl -I -H "Host: img-optimizer-fragrant-cloud-4712.fly.dev" localhost
HTTP/1.1 200 OK
x-powered-by: Express
content-type: image/webp
cache-control: public, max-age=31557600
content-length: 13362
etag: W/"3432-ErSvtwFB99sNclnfEGZiVbVoDqA"
date: Sat, 18 May 2024 08:27:28 GMT
server: Fly/6751cc4d (2024-05-14)
fly-request-id: 01HY5D09XCGYN9G8E654RTSBJW-ams
X-Varnish: 32779 32774
Age: 214
Via: 1.1 fly.io, 1.1 varnish (Varnish/7.3)
Accept-Ranges: bytes
Connection: keep-alive
The easiest way to fix the issue without being forced to use this Host header is by setting it in VCL:
sub vcl_recv {
set req.http.Host = "img-optimizer-fragrant-cloud-4712.fly.dev";
}
However, if your plan is to eventually use that img-optimizer-fragrant-cloud-4712.fly.dev hostname, simply changing the DNS to the Varnish server will do the trick.