Varnish returns 503 error, because it "Could not get storage"
Marco Dickert - evolver group
marco.dickert at evolver.de
Wed Aug 18 08:02:08 UTC 2021
Hi all,
I'm still investigating issues with one of our varnish instances. We
use varnish as a cache and loadbalancer behind nginx and in front of a
docker platform. We experienced an outage for about 20 minutes as
clients received 503 errors being produced by varnish while the docker
containers responded correct (according to the containers' logs).
Setup is:
[ nginx ==> varnish ] ==> [ docker swarm (4 hosts, lots of containers) ]
Sites are distinguished by the exposed ports of the respective swarm
services. Mapping site to service is done with a director containing
the 4 hosts and the respective service port as backends.
By comparing nginx logs with container logs we could confirm varnish
being the culprit. It seemed like the backend request succeeds, but
varnish returns a 503 error anyway.
To investigate further, I activated some logging, which revealed some
concerning information. Apparently varnish sometimes has problems with
the storage, as the "FetchError" says "Could not get storage".
```
* << BeReq >> 70780723
- Begin bereq 70780722 pass
[...]
- Storage malloc Transient
- Fetch_Body 2 chunked -
- FetchError Could not get storage
```
I have attached two complete log examples to this mail.
I did some extensive searching including the varnish book and stuff but
so far did not come up with an explanation. Can anyone help understand
why this happens and how to avoid it?
Here are some additional information about our varnish instance:
- Debian buster
- system: HP DL360p G8, 32G RAM, Intel Xeon E5-2630
- varnish 6.6.0-1~buster (using the varnish repos)
- varnish start options:
```
ExecStart=/usr/sbin/varnishd -a :6081 \
-T :6082 \
-f /etc/varnish/default.vcl \
-p ping_interval=6 -p cli_timeout=10 -p pipe_timeout=600 \
-p listen_depth=4096 -p thread_pool_min=200
-p thread_pool_max=500 -p workspace_client=128k
-p nuke_limit=1000 -S /etc/varnish/secret \
-s malloc,12G \
-s Transient=malloc,3500M
```
Thanks in advance!
--
Marco Dickert
-------------- next part --------------
* << BeReq >> 1013636267
- Begin bereq 1013636266 pass
- VCL_use xxx
- Timestamp Start: 1629187432.080789 0.000000 0.000000
- BereqMethod GET
- BereqURL /fonts/vendor/@fortawesome/fontawesome-pro/webfa-solid-900.woff2?978b27ec5d8b81d2b15aa28aaaae1fcb
- BereqProtocol HTTP/1.0
- BereqHeader Host: xxx
- BereqHeader X-Real-IP: 46.114.x.x
- BereqHeader X-Forwarded-Proto: https
- BereqHeader Front-End-Https: on
- BereqHeader user-agent: Mozilla/5.0 (Android 10; Mobile; rv:91.0) Gecko/91.0 Firefox/91.0
- BereqHeader accept: application/font-woff2;q=1.0,application/font-woff;q=0.9,*/*;q=0.8
- BereqHeader accept-language: de-DE
- BereqHeader accept-encoding: identity
- BereqHeader referer: xxx
- BereqHeader sec-fetch-dest: font
- BereqHeader sec-fetch-mode: cors
- BereqHeader sec-fetch-site: same-origin
- BereqHeader dnt: 1
- BereqHeader sec-gpc: 1
- BereqHeader X-Forwarded-For: 46.114.x.x
- BereqHeader cookie: __cmpcc=1; XSRF-TOKEN=xxxxxxxxxxxxxxxxxxxx
- BereqHeader X-CMS-Environment: zeitungsportal
- BereqHeader X-SEGMENT: GRP0
- BereqHeader X-iat: 1628771228
- BereqHeader x-token-status: expired
- BereqHeader X-Return-URL: xxx
- BereqProtocol HTTP/1.1
- BereqHeader X-Varnish: 1013636267
- VCL_call BACKEND_FETCH
- VCL_return fetch
- Timestamp Fetch: 1629187432.080825 0.000036 0.000036
- Timestamp Connected: 1629187432.080832 0.000043 0.000007
- BackendOpen 419 docker_1_8080 10.132.100.1 8080 192.168.11.32 40538 reuse
- Timestamp Bereq: 1629187432.080880 0.000091 0.000047
- Timestamp Beresp: 1629187432.082310 0.001521 0.001429
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Tue, 17 Aug 2021 08:03:51 GMT
- BerespHeader Server: Apache
- BerespHeader Last-Modified: Tue, 03 Aug 2021 13:38:39 GMT
- BerespHeader Accept-Ranges: bytes
- BerespHeader Content-Length: 136824
- BerespHeader Cache-Control: max-age=31536000
- BerespHeader Expires: Wed, 17 Aug 2022 08:03:51 GMT
- BerespHeader Access-Control-Allow-Origin: *
- BerespHeader Content-Type: font/woff2
- VCL_call BACKEND_RESPONSE
- BerespHeader x-host: xxx
- BerespHeader x-url: /fonts/vendor/@fortawesome/fontawesome-pro/webfa-solid-900.woff2?978b27ec5d8b81d2b15aa28aaaae1fcb
- BereqUnset cookie: __cmpcc=1; XSRF-TOKEN=xxxxxxxxxxxxxxxxxx
- VCL_return deliver
- Timestamp Process: 1629187432.082324 0.001535 0.000014
- Filters esi
- Storage malloc Transient
- Fetch_Body 3 length -
- ESI_xmlerror No ESI processing, first char not '<'. (See feature esi_disable_xml_check)
- FetchError Could not get storage
- BackendClose 419 docker_1_8080 close
- Timestamp Error: 1629187432.086258 0.005469 0.003933
- BerespProtocol HTTP/1.1
- BerespStatus 503
- BerespReason Backend fetch failed
- BerespHeader Date: Tue, 17 Aug 2021 08:03:52 GMT
- BerespHeader Server: Varnish
- VCL_call BACKEND_ERROR
- BerespHeader Content-Type: text/html; charset=iso8859-1
- VCL_return deliver
- Storage malloc Transient
- Length 17892
- BereqAcct 2859 0 2859 295 91928 92223
- End
-------------- next part --------------
* << BeReq >> 73306576
- Begin bereq 73306575 fetch
- VCL_use xxx
- Timestamp Start: 1629187693.112352 0.000000 0.000000
- BereqMethod GET
- BereqURL /media/Lesermarkt/Aboservice-Mailings/Coronavvirus_320x300.jpg
- BereqProtocol HTTP/1.0
- BereqHeader Host: xxx
- BereqHeader X-Real-IP: 92.117.x.x
- BereqHeader X-Forwarded-Proto: https
- BereqHeader Front-End-Https: on
- BereqHeader user-agent: Mozilla/5.0 (Linux; Android 7.0; BLN-L21 Build/HONORBLN-L21; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/92.0.4515.131 Mobile Safari/537.36
- BereqHeader accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
- BereqHeader x-requested-with: com.android.email
- BereqHeader sec-fetch-site: cross-site
- BereqHeader sec-fetch-mode: no-cors
- BereqHeader sec-fetch-dest: image
- BereqHeader accept-language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7
- BereqHeader X-Forwarded-For: 92.117.x.x
- BereqHeader Accept-Encoding: gzip
- BereqProtocol HTTP/1.1
- BereqHeader X-Varnish: 73306576
- VCL_call BACKEND_FETCH
- VCL_return fetch
- Timestamp Fetch: 1629187693.112391 0.000038 0.000038
- Timestamp Connected: 1629187693.112398 0.000045 0.000006
- BackendOpen 364 docker_1_8128 10.132.100.1 8128 192.168.11.32 56088 reuse
- Timestamp Bereq: 1629187693.112428 0.000075 0.000030
- Timestamp Beresp: 1629187693.115675 0.003322 0.003246
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Tue, 17 Aug 2021 08:08:12 GMT
- BerespHeader Server: Apache/2.4.38 (Debian)
- BerespHeader Last-Modified: Tue, 22 Sep 2020 09:18:06 GMT
- BerespHeader ETag: "155687-5afe371e05d32"
- BerespHeader Accept-Ranges: bytes
- BerespHeader Content-Length: 1398407
- BerespHeader Content-Type: image/jpeg
- TTL RFC 120 10 0 1629187693 1629187693 1629187692 0 0 cacheable
- VCL_call BACKEND_RESPONSE
- BerespHeader x-host: xxx
- BerespHeader x-url: /media/Lesermarkt/Aboservice-Mailings/Coronavvirus_320x300.jpg
- TTL VCL 120 10 0 1629187693 uncacheable
- VCL_return deliver
- Timestamp Process: 1629187693.115703 0.003350 0.000028
- Filters esi
- Storage malloc Transient
- Fetch_Body 3 length -
- ESI_xmlerror No ESI processing, first char not '<'. (See feature esi_disable_xml_check)
- FetchError Could not get storage
- BackendClose 364 docker_1_8128 close
- Timestamp Error: 1629187693.120795 0.008442 0.005092
- BerespProtocol HTTP/1.1
- BerespStatus 503
- BerespReason Backend fetch failed
- BerespHeader Date: Tue, 17 Aug 2021 08:08:13 GMT
- BerespHeader Server: Varnish
- VCL_call BACKEND_ERROR
- BerespHeader Content-Type: text/html; charset=iso8859-1
- VCL_return deliver
- Storage malloc Transient
- Length 17892
- BereqAcct 662 0 662 237 137815 138052
- End
More information about the varnish-misc
mailing list