Details
-
Bug
-
Resolution: Unresolved
-
High
-
None
-
1.10.1, 1.13.0
-
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
Issue Links
- relates to
-
EZP-27716 ESI not cacheable on default ezplatform-demo installation
- Open