Join Log in
Score:0
Erich avatar Server

Varnish 4.1 - How to serve cached copy on backend fetch failed instead of 503

sn flag
Erich

I have a site served by apache+tomcat and a cache served by Varnish 4.1

When apache is down, varnish always returns a 503 error.
I would like varnish to return the copy of the pages it has in its cache but my attempts with ttl and grace have been unsuccessful.
I think I've read all the documentation on varnish 4.1 that I could find, any help is really appreciated.

Thanks in advance

EDIT: varnishlog -g request -q "ReqUrl eq '/'"

curl

*   << Request  >> 1410492
-   Begin          req 1410491 rxreq
-   Timestamp      Start: 1646995409.603391 0.000000 0.000000
-   Timestamp      Req: 1646995409.603391 0.000000 0.000000
-   ReqStart       10.xxx.xxx.xxx 57472
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      host: akamai5.rsi.ch
-   ReqHeader      user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:98.0) Gecko/20100101 Firefox/98.0
-   ReqHeader      accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8
-   ReqHeader      accept-language: it,en-US;q=0.7,en;q=0.3
-   ReqHeader      accept-encoding: gzip, deflate, br
-   ReqHeader      cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; __utma=46365988.836346559.1644414441.16
-   ReqHeader      upgrade-insecure-requests: 1
-   ReqHeader      sec-fetch-dest: document
-   ReqHeader      sec-fetch-mode: navigate
-   ReqHeader      sec-fetch-site: none
-   ReqHeader      sec-fetch-user: ?1
-   ReqHeader      cache-control: max-age=0
-   ReqHeader      x-forwarded-proto: https
-   ReqHeader      x-forwarded-ssl: on
-   ReqHeader      x-forwarded-port: 443
-   ReqHeader      x-forwarded-for: 1178.xxx.xxx.xxx
-   ReqHeader      connection: close
-   ReqUnset       x-forwarded-for: 1178.xxx.xxx.xxx
-   ReqHeader      X-Forwarded-For: 1178.xxx.xxx.xxx, 10.xxx.xxx.xxx
-   VCL_call       RECV
-   ReqUnset       cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; __utma=46365988.836346559.1644414441.16
-   ReqHeader      Cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; cs_fpid=1645804349272_22538249; wt_geid
-   ReqUnset       Cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; cs_fpid=1645804349272_22538249; wt_geid
-   ReqHeader      Cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; cs_fpid=1645804349272_22538249; wt_geid
-   ReqUnset       Cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; cs_fpid=1645804349272_22538249; wt_geid
-   ReqHeader      Cookie: wt_rla=292330999892453%2C2%2C1646731482026; _pipe_c=do_not_track; _ga=GA1.2.836346559.1644414441; __gads=ID=453223b8518b57e5-22f191e137cd00c3:T=1644414444:RT=1644414444:S=ALNI_MbCUi8liJ5sbhjlTe68z1BhLhZJCQ; cs_fpid=1645804349272_22538249; wt_geid
-   VCL_return     hash
-   ReqUnset       accept-encoding: gzip, deflate, br
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   Hit            1410469
-   VCL_call       HIT
-   VCL_return     deliver
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Fri, 11 Mar 2022 10:42:05 GMT
-   RespHeader     Server: Apache-Coyote/1.1
-   RespHeader     Content-Type: text/html;charset=UTF-8
-   RespHeader     Set-Cookie: JSESSIONID=F8D07853DF7D90A3F381B316F64FA285; Path=/; HttpOnly
-   RespHeader     X-Varnish: 1410492 1410469
-   RespHeader     Age: 84
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache-Host: rsi-prod-varnish45
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     X-XSS-Protection: 1; mode=block
-   RespHeader     X-Content-Type-Options: nosniff
-   RespHeader     Content-Security-Policy: script-src 'self' 'unsafe-inline' 'unsafe-eval' *
-   RespHeader     X-Cache: HIT
-   RespHeader     X-Cache-Hits: 3
-   RespHeader     X-Grace-Hit: yes
-   VCL_return     deliver
-   Timestamp      Process: 1646995409.603614 0.000222 0.000222
-   RespHeader     Accept-Ranges: bytes
-   RespHeader     Content-Length: 191244
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1646995409.608024 0.004632 0.004410
-   ReqAcct        1130 0 1130 574 191244 191818
-   End

browser

*   << Request  >> 1410496
-   Begin          req 1410495 rxreq
-   Timestamp      Start: 1646995426.730217 0.000000 0.000000
-   Timestamp      Req: 1646995426.730217 0.000000 0.000000
-   ReqStart       10.xxx.xxx.xxx 60908
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      host: www.example.com
-   ReqHeader      user-agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0
-   ReqHeader      accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   ReqHeader      accept-language: it,it-IT;q=0.8,en-US;q=0.5,en;q=0.3
-   ReqHeader      accept-encoding: gzip, deflate, br
-   ReqHeader      cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; __utma=46365988.1217589648.1620392041.1638545296.1642173864.10; __utmz=46365988.16
-   ReqHeader      upgrade-insecure-requests: 1
-   ReqHeader      cache-control: max-age=0
-   ReqHeader      x-forwarded-proto: https
-   ReqHeader      x-forwarded-ssl: on
-   ReqHeader      x-forwarded-port: 443
-   ReqHeader      x-forwarded-for: 178.xxx.xxx.xxx
-   ReqHeader      connection: close
-   ReqUnset       x-forwarded-for: 178.xxx.xxx.xxx
-   ReqHeader      X-Forwarded-For: 178.xxx.xxx.xxx, 10.xxx.xxx.xxx
-   VCL_call       RECV
-   ReqUnset       cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; __utma=46365988.1217589648.1620392041.1638545296.1642173864.10; __utmz=46365988.16
-   ReqHeader      Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
-   ReqUnset       Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
-   ReqHeader      Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
-   ReqUnset       Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
-   ReqHeader      Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
-   VCL_return     hash
-   ReqUnset       accept-encoding: gzip, deflate, br
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 1410497 fetch
-   Timestamp      Fetch: 1646995426.730455 0.000238 0.000238
-   RespProtocol   HTTP/1.1
-   RespStatus     503
-   RespReason     Backend fetch failed
-   RespHeader     Date: Fri, 11 Mar 2022 10:43:46 GMT
-   RespHeader     Server: Varnish
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   RespHeader     X-Varnish: 1410496
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache-Host: rsi-prod-varnish45
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     X-XSS-Protection: 1; mode=block
-   RespHeader     X-Content-Type-Options: nosniff
-   RespHeader     Content-Security-Policy: script-src 'self' 'unsafe-inline' 'unsafe-eval' *
-   RespHeader     X-Cache: HIT
-   RespHeader     X-Cache-Hits: 0
-   RespHeader     X-Grace-Hit: yes
-   VCL_return     deliver
-   Timestamp      Process: 1646995426.730495 0.000278 0.000040
-   RespHeader     Content-Length: 284
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1646995426.730527 0.000310 0.000032
-   ReqAcct        929 0 929 490 284 774
-   End
**  << BeReq    >> 1410497
--  Begin          bereq 1410496 fetch
--  Timestamp      Start: 1646995426.730367 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /
--  BereqProtocol  HTTP/1.1
--  BereqHeader    host: www.example.com
--  BereqHeader    user-agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0
--  BereqHeader    accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
--  BereqHeader    accept-language: it,it-IT;q=0.8,en-US;q=0.5,en;q=0.3
--  BereqHeader    upgrade-insecure-requests: 1
--  BereqHeader    x-forwarded-proto: https
--  BereqHeader    x-forwarded-ssl: on
--  BereqHeader    x-forwarded-port: 443
--  BereqHeader    X-Forwarded-For: 178.xxx.xxx.xxx, 10.xxx.xxx.xxx
--  BereqHeader    Cookie: _pipe_c=do_not_track; _ga=GA1.2.1217589648.1620392041; __gads=ID=1a22b33c44d55e6f-1a22b33c44d55e6f:T=1620392042:RT=1620392042:S=ALNI_MYR9nyXrxcQ8QV1Y2pNVDp67Gn9-w; wt_rla=292330999892453%2C2%2C1646995242972; cs_fpid=1645855325408_55998969; JSESSI
--  BereqHeader    Accept-Encoding: gzip
--  BereqHeader    X-Varnish: 1410497
--  VCL_call       BACKEND_FETCH
--  VCL_Log        Backend fetch: v_ssl_ece
--  VCL_return     fetch
--  FetchError     Director v_ssl_ece returned no backend
--  FetchError     No backend
--  Timestamp      Beresp: 1646995426.730387 0.000020 0.000020
--  Timestamp      Error: 1646995426.730390 0.000023 0.000003
--  BerespProtocol HTTP/1.1
--  BerespStatus   503
--  BerespReason   Service Unavailable
--  BerespReason   Backend fetch failed
--  BerespHeader   Date: Fri, 11 Mar 2022 10:43:46 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
--  ObjProtocol    HTTP/1.1
--  ObjStatus      503
--  ObjReason      Backend fetch failed
--  ObjHeader      Date: Fri, 11 Mar 2022 10:43:46 GMT
--  ObjHeader      Server: Varnish
--  ObjHeader      Content-Type: text/html; charset=utf-8
--  ObjHeader      Retry-After: 5
--  Length         284
--  BereqAcct      0 0 0 0 0 0
--  End

EDIT 2: hash and cookies

After much investigation we discovered that the problem lies in this configuration:

sub vcl_hash {
  hash_data( req.url );
  if( req.http.host ) {
    hash_data( req.http.host );
  } else {
    hash_data( server.ip );
  }
  # hash cookies for object with auth
  if( req.http.Cookie ) {
    hash_data( req.http.Cookie );
  }
  return( lookup );
}

If cookies are removed from the varnish hash it returns the cache correctly. Is it useful for cookies to be included in the hash? At first glance I think so, if cookies are used to keep track of user authentication. How can we include only certain cookies in the hash (e.g. those from an authenticated session) and not those that are not useful for caching (e.g. those related to analytics)?

82
0 + 0
Score:0
Thijs Feryn avatar Server
in flag
Thijs Feryn

As long as the sum of the TTL and grace values are greater than zero, no backend fetches are made.

If your TTL expires, grace mode will ensure that stale content is served while a fetch attempt is made.

Grace, which is a stale-while-revalidate mechanism, can actually be abused and turned into a stale-if-error mechanism. By setting the grace high enough, users will never experience the downtime of the backend.

Here's some VCL:

vcl 4.1;

import std;

sub vcl_recv {
    if (std.healthy(req.backend_hint)) {
        set req.grace = 10s;
    }
}

sub vcl_backend_response {
    set beresp.grace = 24h;
}

This VCL code will enforce a 24-hour grace. This means your backend can be down for a day without anyone noticing. However, as long as the backend is healthy, Varnish will only use 10 seconds of grace.

It's important that your backend definition has a .probe property that refers to a health checking probe, otherwise std.healthy(req.backend_hint) will never be able to produce the right results.

I used set beresp.grace = 24h which might be excessive. By setting the grace to such a high duration, these objects remain in the cache while being expired. If you have a large catalog of content that needs to be cached, this may effect your hit rate and may cause forced cache eviction when the cache is full.

IMPORTANT: Varnish Cache 4.1 is end-of-life and should not be used. Please install Varnish 6.0 LTS or Varnish 7 instead.

My VCL example contains a vcl 4.1; version marker which will only work in Varnish 6 or Varnish 7. I do this on purpose to encourage users to use recent versions of Varnish. By switching this to vcl 4.0; the code will probably work on older versions of Varnish. Please consider upgrading.

503 error

Based on the VSL output that you added to your question, I can conclude that you have defined and used a director object in your VCL that doesn't have any backends.

This is the error I found in your VSL output:

Director v_ssl_ece returned no backend

Please have a look at the director named v_ssl_ece.

  • Check whether or not you need this director
  • Check if it is assigned correctly through req.backend_hint in vcl_recv or through bereq.backend in vcl_backend_fetch
  • Check why v_ssl_ece doesn't have any backends

If you cannot find the solution, please share your full VCL file so I can assist.

0 + 0
Erich avatar
sn flag
Erich
Thank you very much! Unfortunately I can't update varnish to the new version :-/ Your solution works very well if I use curl, but if I use a browser (chrome or firefox) varnish returns a 503 error. I tried simulating a firefox request with curl using all the http headers firefox sends to the server but varnish returns 200 OK if I use curl and 503 if I use firefox. Do you have any clues about this? Thanks again
0
Reply
Thijs Feryn avatar
in flag
Thijs Feryn
Please add the output of `varnishlog -g request -q "ReqUrl eq '/'"` to the question. This command will print the logs for the homepage. Ensure you're using the browser to call the homepage. If you get the error, the logs might tell us why.
0
Reply
Erich avatar
sn flag
Erich
I added the output of `varnishlog -g request -q "ReqUrl eq '/'"` to the question, both for a request from curl and a request from firefox. Do see any something that could help me us? Thanks again
0
Reply
Thijs Feryn avatar
in flag
Thijs Feryn
@Erich I updated the answer with information regarding the VSL output
0
Reply
Erich avatar
sn flag
Erich
Sorry for my late reply, we struggled a lot to find the problem. I updated my question again and I hope you have some useful suggestions. Thank you very much!
0
Reply
Thijs Feryn avatar
in flag
Thijs Feryn
@Erich Please don't add the cookies to the hash, because it will cause too many cache variations and too many misses. If you want to create cache variations based on cookie values, please extract select cookies and validate their content to avoid filling up your cache with meaningless cache variations.
0
Reply
Thijs Feryn avatar
in flag
Thijs Feryn
@Erich Please also add your full VCL code, not just the `hash_data` extract. I want to understand what's really going on and tell you what to change to enforce *stale if error* behavior when the backend is down. My initial feedback is that the `Set-Cookie: JSESSIONID=F8D07853DF7D90A3F381B316F64FA285; Path=/; HttpOnly` could be the reason why the content is not stored in cache. See https://www.varnish-software.com/developers/tutorials/varnish-builtin-vcl/#dont-cache-responses-with-set-cookie-headers for more information.
0
Reply
ธงชาติไทย
Elon Musk
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.