Uploaded image for project: 'eZ Platform Enterprise Edition'
  1. eZ Platform Enterprise Edition
  2. EZEE-1693

ESI for language_switcher ( and others ) is not cachable by varnish

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: High High
    • None
    • 1.10.1, 1.13.0
    • Landing Page Manager, Studio Demo Bundle
    • None

    • varnish4, nginx, php-fpm

    Description

      There are a few ESI calls which are not cachable for varnish.

      Doing this call twice : 

      curl -sD - -o /dev/null --cookie "eZSESSID98defd6ee70dfb1dea416cecdf391f58=c65an2in8ptqhig6osp4l3ecbb" http://localhost:8081
curl -sD - -o /dev/null --cookie "eZSESSID98defd6ee70dfb1dea416cecdf391f58=c65an2in8ptqhig6osp4l3ecbb" http://localhost:8081

      The nginx logs for the second request reveals that calls are not cached

      172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=template%3DeZStudioDemoBundle%253Aparts%253Alanguage_switcher.html.twig%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dezstudiodemo.controller.language_switcher%253Ashow&_hash=4zqoFT2J0v9NpKpNDvZ6ch%2FjhPjBqwaDLUf7co8uqzA%3D HTTP/1.1" 200 2734 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-5d5a0808-bd49-0e85-650c-c915e73b51cd%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=96CMO7fH7rzRuDxt1%2Fz%2FKRBwHd9cv3z8c%2BiQ2y6H4V8%3D HTTP/1.1" 200 679 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-83fc6e49-d87f-9387-e4e1-b0951a3d9055%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=ZVB%2Bx8GCrY609iu9fv0GD5VXCXQT6llbGFN5BNiYYAo%3D HTTP/1.1" 200 10361 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-294fbffd-744a-6ac6-3f29-9783799c10f6%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=aWxTFx1WpEbsLHRVaRdyNdoYthpk7imhQQ6IfE1SF3Q%3D HTTP/1.1" 200 533 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-96ba244b-c72d-740d-0ccd-fdcec4e23af4%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=GUqqvirS3UB3IdCohGbgTX5XSGnQFvH%2B5RcVx252Qug%3D HTTP/1.1" 200 465 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-b27742d1-628f-0c8c-a48b-0b1dd0d7e5f9%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=fi7AJ5GXnLbL8maD37elGqnC8sSS23cPNyl7Ij4ZDn0%3D HTTP/1.1" 200 3656 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-bf850b3f-e770-6e8f-46d0-ceff8d0c94f4%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=4965Dd6FS5jIkQmhT9gFop7zx227fBgUshg9oTVRfLw%3D HTTP/1.1" 200 467 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"
172.24.0.5 - - [27/Jul/2017:13:46:55 +0000] "GET /_fragment?_path=contentId%3D63%26blockId%3Db-b3a66965-cec8-8c27-bb5c-a773e26bad3a%26versionNo%3D1%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253A%2522site%2522%253Bs%253A12%253A%2522matchingType%2522%253Bs%253A7%253A%2522default%2522%253Bs%253A7%253A%2522matcher%2522%253BN%253B%257D%26_format%3Dhtml%26_locale%3Den_GB%26_controller%3Dez_block%253ArenderBlockAction&_hash=TeHZlJC%2BDt1JICT%2BFgZw3ce%2B1JvFyfCsbJIELV7umU4%3D HTTP/1.1" 200 3656 "-" "curl/7.47.0" "172.24.0.1, 172.24.0.1"

      varnishlog reveals that in the first request ("GET /_fragment?_path=template%3DeZStudioDemoBundle%253Aparts%253Alanguage_switcher.html.twig(...)") the back-end responds with "Cache-Control: no-cache"

      # varnishlog -g request
(...)
*** << BeReq    >> 32874     
--- Begin          bereq 32873 fetch
--- Timestamp      Start: 1501163214.896289 0.000000 0.000000
--- BereqMethod    GET
--- BereqURL       /_fragment?_path=template%3DeZStudioDemoBundle%253Aparts%253Alanguage_switcher.html.twig%26serialized_siteaccess%3DO%253A38%253A%2522eZ%255CPublish%255CCore%255CMVC%255CSymfony%255CSiteAccess%2522%253A3%253A%257Bs%253A4%253A%2522name%2522%253Bs%253A4%253
--- BereqProtocol  HTTP/1.1
--- BereqHeader    Host: localhost:8081
--- BereqHeader    User-Agent: curl/7.47.0
--- BereqHeader    x-user-hash: b1731d46b0e7a375a5b024e950fdb8d49dd25af85a5c7dd5116ad2a18cda82cb
--- BereqHeader    Surrogate-Capability: abc=ESI/1.0
--- BereqHeader    X-Forwarded-For: 172.24.0.1, 172.24.0.1
--- BereqHeader    accept: */*
--- BereqHeader    cookie: eZSESSID98defd6ee70dfb1dea416cecdf391f58=c65an2in8ptqhig6osp4l3ecbb
--- BereqHeader    Accept-Encoding: gzip
--- BereqHeader    X-Varnish: 32874
--- VCL_call       BACKEND_FETCH
--- VCL_return     fetch
--- BackendOpen    24 boot.ezplatform 172.24.0.4 80 172.24.0.5 55364
--- BackendStart   172.24.0.4 80
--- Timestamp      Bereq: 1501163214.896468 0.000179 0.000179
--- Timestamp      Beresp: 1501163215.000596 0.104307 0.104128
--- BerespProtocol HTTP/1.1
--- BerespStatus   200
--- BerespReason   OK
--- BerespHeader   Server: nginx/1.8.1
--- BerespHeader   Content-Type: text/html; charset=UTF-8
--- BerespHeader   Transfer-Encoding: chunked
--- BerespHeader   Connection: keep-alive
--- BerespHeader   X-Powered-By: PHP/7.1.2
--- BerespHeader   Cache-Control: no-cache
--- BerespHeader   Date: Thu, 27 Jul 2017 13:46:54 GMT
--- BerespHeader   X-Cache-Debug: 1
--- BerespHeader   Vary: X-User-Hash
--- BerespHeader   X-Debug-Token: 750359
--- BerespHeader   X-Debug-Token-Link: http://localhost:8081/_profiler/750359
--- TTL            RFC 120 10 0 1501163215 1501163215 1501163214 0 0
--- VCL_call       BACKEND_RESPONSE
--- TTL            VCL 120 3600 0 1501163215
--- TTL            VCL 120 3600 0 1501163215
--- VCL_return     deliver
--- Storage        malloc Transient
--- ObjProtocol    HTTP/1.1
--- ObjStatus      200
--- ObjReason      OK
--- ObjHeader      Server: nginx/1.8.1
--- ObjHeader      Content-Type: text/html; charset=UTF-8
--- ObjHeader      X-Powered-By: PHP/7.1.2
--- ObjHeader      Cache-Control: no-cache
--- ObjHeader      Date: Thu, 27 Jul 2017 13:46:54 GMT
--- ObjHeader      X-Cache-Debug: 1
--- ObjHeader      Vary: X-User-Hash
--- ObjHeader      X-Debug-Token: 750359
--- ObjHeader      X-Debug-Token-Link: http://localhost:8081/_profiler/750359
--- Fetch_Body     2 chunked stream
--- BackendReuse   24 boot.ezplatform
--- Timestamp      BerespBody: 1501163215.000823 0.104534 0.000226
--- Length         2722
--- BereqAcct      900 0 900 339 2722 3061
--- End
(...)

      I assume it should return a s-maxage instead?

      The same goes for other ESI (which is called multiple times) I guess

      System setup using :

      export COMPOSE_FILE=doc/docker-compose/base-dev.yml
docker-compose -f doc/docker-compose/install.yml up --abort-on-container-exit
# Next, change X-User-Hash from '38015b703d82206ebc01d17a39c727e5' to 'b1731d46b0e7a375a5b024e950fdb8d49dd25af85a5c7dd5116ad2a18cda82cb' in doc/varnish/vcl/varnish4.vcl
docker-compose -f doc/docker-compose/base-dev.yml -f doc/docker-compose/varnish.yml up -d --force-recreate

      Attachments

        1. ezee-1693-varnishlog.txt
          88 kB

        Activity

          People

            Unassigned Unassigned
            vidar.langseid@ibexa.co Vidar Langseid
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated: