0

I'm having a weird issue while configuring Varnish with my Magento 2 store. My setup is such that I'm using a frontend server that routes the requests first to Varnish and then to Apache (as a failover, if the request is not available to be served from Varnish cache). Apache is the backend to Varnish. As soon as I configure Magento with Varnish cache from the admin, the page doesn't fully and it is displayed only after refreshing the browser a few times.

The page is being displayed like this when Varnish is enabled: https://pasteboard.co/Jvi8hAb.png

This is how it should appear: https://pasteboard.co/Jvi8YN5.png

I only get the full page after I refresh a few times and then it disappears again. I have tried everything available on the internet, cleared cache from everywhere but no luck. I already have set 2048M php memory limit. If I stop the Varnish service, everything works as expected. There might be something I'm missing which is causing the reported issue.

I'm using the following VCL. https://gist.github.com/dvershinin/de91aa78a96ae9f6e8d2950b3e1463a4

The curl response I'm getting is:

HTTP/2 200 
server: <server-name>
date: <date>
content-type: text/html; charset=UTF-8
x-content-type-options: nosniff
x-xss-protection: 1; mode=block
x-frame-options: SAMEORIGIN
vary: Accept-Encoding
pragma: no-cache
expires: -1
cache-control: no-store, no-cache, must-revalidate, max-age=0
x-magento-cache-debug: HIT
accept-ranges: bytes

I'm using Magento 2.3.3 with Varnish 6.0 on Debian 10. There's not much information I was able to find on the internet of the similar issue. Any help to fix this would be highly appreciated

EDIT: The systemd configuration is as follows:

[Unit]
Description=Varnish HTTP accelerator
Documentation=https://www.varnish-cache.org/docs/6.1/ man:varnishd

[Service]
Type=simple
LimitNOFILE=131072
LimitMEMLOCK=82000
ExecStart=/usr/sbin/varnishd -j unix,user=vcache -F -a :8080 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m
ExecReload=/usr/share/varnish/varnishreload
ProtectSystem=full
ProtectHome=true
PrivateTmp=true
PrivateDevices=true

[Install]
WantedBy=multi-user.target

Varnish status show the following results:

● varnish.service - Varnish HTTP accelerator
   Loaded: loaded (/etc/systemd/system/varnish.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-10-12 10:47:40 UTC; 59min ago
     Docs: https://www.varnish-cache.org/docs/6.1/
           man:varnishd
 Main PID: 25408 (varnishd)
    Tasks: 217 (limit: 1164)
   Memory: 26.8M
   CGroup: /system.slice/varnish.service
           ├─25408 /usr/sbin/varnishd -j unix,user=vcache -F -a :8080 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m
           └─26429 /usr/sbin/varnishd -j unix,user=vcache -F -a :8080 -T localhost:6082 -f /etc/varnish/default.vcl -S /etc/varnish/secret -s malloc,256m

Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]:   },
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: },
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: thr.busyobj = (nil) {
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: },
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Debug: Child cleanup complete
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Child cleanup complete
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Debug: Child (26429) Started
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Child (26429) Started
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Info: Child (26429) said Child starts
Oct 12 11:05:40 ip-172-26-11-138 varnishd[25408]: Child (26429) said Child starts

Varnishlog output:

*   << Request  >> 32774     
-   Begin          req 32773 rxreq
-   Timestamp      Start: 1602503863.156404 0.000000 0.000000
-   Timestamp      Req: 1602503863.156404 0.000000 0.000000
-   ReqStart       127.0.0.1 49416 a0
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.0
-   ReqHeader      Host: <host>
-   ReqHeader      X-Real-IP: <myip>
-   ReqHeader      X-Forwarded-For: <myip>
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      X-Forwarded-Host: <hostname>
-   ReqHeader      Connection: close
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 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: en-US,en;q=0.9
-   ReqUnset       X-Forwarded-For: <myip>
-   ReqHeader      X-Forwarded-For: <myip>, 127.0.0.1
-   VCL_call       RECV
-   ReqUnset       X-Forwarded-For: <myip>, 127.0.0.1
-   ReqHeader      x-forwarded-for: <myip>, 127.0.0.1, 127.0.0.1
-   ReqURL         /
-   ReqURL         /
-   ReqURL         /
-   ReqURL         /
-   VCL_return     hash
-   ReqUnset       Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 32775 fetch
-   Timestamp      Fetch: 1602503868.621473 5.465069 5.465069
-   RespProtocol   HTTP/1.1
-   RespStatus     302
-   RespReason     Found
-   RespHeader     Date: Mon, 12 Oct 2020 11:57:43 GMT
-   RespHeader     Server: Apache (Debian)
-   RespHeader     Pragma: no-cache
-   RespHeader     Cache-Control: max-age=0, must-revalidate, no-cache, no-store
-   RespHeader     Expires: Sat, 12 Oct 2019 11:57:48 GMT
-   RespHeader     X-Content-Type-Options: nosniff
-   RespHeader     X-XSS-Protection: 1; mode=block
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     Set-Cookie: PHPSESSID=jv767e8k06uff8dtf286ulobtr; expires=Mon, 12-Oct-2020 12:57:48 GMT; Max-Age=3600; path=/; domain=feed.samplewebsites.ml; HttpOnly
-   RespHeader     Location: <url>
-   RespHeader     Content-Length: 0
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     X-Varnish: 32774
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/6.1)
-   VCL_call       DELIVER
-   RespHeader     X-Magento-Cache-Debug: MISS
-   RespUnset      Age: 0
-   RespUnset      Server: Apache
-   RespUnset      X-Varnish: 32774
-   RespUnset      Via: 1.1 varnish (Varnish/6.1)
-   VCL_return     deliver
-   Timestamp      Process: 1602503868.621500 5.465095 0.000026
-   RespHeader     Connection: close
-   Timestamp      Resp: 1602503868.621534 5.465130 0.000035
-   ReqAcct        638 0 638 577 0 577
-   End            
**  << BeReq    >> 32775     
--  Begin          bereq 32774 fetch
--  Timestamp      Start: 1602503863.156493 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /
--  BereqProtocol  HTTP/1.0
--  BereqHeader    Host: <host>
--  BereqHeader    X-Real-IP: <myip>
--  BereqHeader    X-Forwarded-Proto: http
--  BereqHeader    X-Forwarded-Host: <host>
--  BereqHeader    Upgrade-Insecure-Requests: 1
--  BereqHeader    User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 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-Language: en-US,en;q=0.9
--  BereqHeader    x-forwarded-for: <myip>, 127.0.0.1, 127.0.0.1
--  BereqHeader    Accept-Encoding: gzip
--  BereqProtocol  HTTP/1.1
--  BereqHeader    X-Varnish: 32775
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  BackendOpen    25 default 127.0.0.1 8081 127.0.0.1 47158
--  BackendStart   127.0.0.1 8081
--  Timestamp      Bereq: 1602503863.156640 0.000148 0.000148
--  Timestamp      Beresp: 1602503868.621315 5.464822 5.464674
--  BerespProtocol HTTP/1.1
--  BerespStatus   302
--  BerespReason   Found
--  BerespHeader   Date: Mon, 12 Oct 2020 11:57:43 GMT
--  BerespHeader   Server: Apache (Debian)
--  BerespHeader   Pragma: no-cache
--  BerespHeader   Cache-Control: max-age=0, must-revalidate, no-cache, no-store
--  BerespHeader   Expires: Sat, 12 Oct 2019 11:57:48 GMT
--  BerespHeader   X-Content-Type-Options: nosniff
--  BerespHeader   X-XSS-Protection: 1; mode=block
--  BerespHeader   X-Frame-Options: SAMEORIGIN
--  BerespHeader   Set-Cookie: PHPSESSID=jv767e8k06uff8dtf286ulobtr; expires=Mon, 12-Oct-2020 12:57:48 GMT; Max-Age=3600; path=/; domain=feed.samplewebsites.ml; HttpOnly
--  BerespHeader   Upgrade: h2,h2c
--  BerespHeader   Connection: Upgrade
--  BerespHeader   Location: <host>
--  BerespHeader   Content-Length: 0
--  BerespHeader   Content-Type: text/html; charset=UTF-8
--  TTL            RFC 0 10 0 1602503869 1602503869 1602503863 1570881468 0 cacheable
--  VCL_call       BACKEND_RESPONSE
--  TTL            VCL 0 10 0 1602503869 cacheable
--  TTL            VCL 0 10 0 1602503869 uncacheable
--  VCL_return     deliver
--  Filters        
--  Storage        malloc Transient
--  Fetch_Body     0 none -
--  BackendReuse   25 default
--  Timestamp      BerespBody: 1602503868.621414 5.464922 0.000100
--  Length         0
--  BereqAcct      650 0 650 599 0 599
--  End            

Log abandoned (vsl)
Log abandoned (vsm)
Log abandoned (vsm)
Log reacquired
Improve this question

2 Answers 2

Reset to default
0

systemd

Please add your systemd runtime configuration for Varnish. I'd like to know which runtime parameters were used to run varnishd.

varnishlog output

The varnishlog binary is your main debugging tool. We will use it to figure out what's going on when Varnish receives a response from the backend.

Please attach the output from the following command to your question:

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

Please make sure you run this command when you're sure the cache for / is empty, because we need to debug both the client-side logic within Varnish, but also the backend-side logic when interacting with the origin server.

I'm assuming the screenshots you added originate from the / homepage. If that's not the case, please change the URL in the varnishlog command.

Improve this answer
2
  • I edited the questions and attached the relevant logs and systemd unit file output
    – faizan
    Commented Oct 12, 2020 at 12:05
  • @faizan You added an HTTP request, which gets redirected to HTTPS. The only think the output shows is an HTTP/302 redirection. Please add a response for the HTTPS version, which doesn't cause a redirect.
    – Thijs Feryn
    Commented Oct 13, 2020 at 7:00
0

I'm using a load balancer that routes the requests first to Varnish and then to Apache (as a failover). As soon as I configure Magento with Varnish cache from the admin, the page doesn't fully and it is displayed only after refreshing the browser a few times.

This is the origin of your issue. As soon as you configure Magento with Varnish support, it chunks some content to ESI blocks, which, Apache cannot process (Varnish can).

In other words, you cannot have Apache as backup to Varnish, because it is not ESI capable. There is a plugin for ESI support, but I don't think it would ever work with Magento 2.

Improve this answer
6
  • Thanks for your answer. I've seen setups that work fine with a load balancer at the front, then Varnish in between and apache at its back, and they just work fine. Can there be any workaround to make this work?
    – faizan
    Commented Oct 12, 2020 at 12:32
  • @faizan perhaps you misworded your setup. Do requests load balance between Varnish and Apache as in your post? (one request goes to Apache, the other to Varnish, at random), or Apache is backend to Varnish.
    – Danila Vershinin
    Commented Oct 12, 2020 at 12:43
  • I'm sorry for the confusion and I edited the answer to avoid confusion. Apache is the backend to Varnish. All incoming requests from the load balancer first fall to Varnish which passes the requests to Apache if the requests are not served from cache.
    – faizan
    Commented Oct 12, 2020 at 12:51
  • Then I would first check the PHP error log first for memory_limit errors, and then var/log/exception.log or var/log/system.log for clues why those blocks fail to render.
    – Danila Vershinin
    Commented Oct 12, 2020 at 12:56
  • I have set the memory limit to 2GB. As per your recommendation, I checked the php access logs and observed two patterns. When the page doesn't fully display, the got something like this: i.imgur.com/s93jLR6.png On a successful load, got something like this: i.imgur.com/G7NFmG5.png Any more guesses?
    – faizan
    Commented Oct 12, 2020 at 14:47

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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