Varnish workshop - Drupal Europe 2018

Ca901ddcea38854b9783781c91fc87c9?s=47 Thijs Feryn
September 11, 2018

Varnish workshop - Drupal Europe 2018

See https://feryn.eu/speaking/varnish-workshop-drupal-europe-2018/ for more information about this Varnish workshop at Drupal Europe 2018.

Ca901ddcea38854b9783781c91fc87c9?s=128

Thijs Feryn

September 11, 2018
Tweet

Transcript

  1. Varnish workshop By Thijs Feryn

  2. Slow websites suck

  3. Web performance is an essential part of the user experience

  4. Slow ~ Down

  5. Saturated market

  6. None
  7. None
  8. None
  9. None
  10. Heavy load

  11. Mo money Mo servers

  12. Refactor slow code Write fast code

  13. After a while you hit the limits

  14. Cache

  15. Don’t recompute if the data hasn’t changed

  16. Caching is not a compensation for poor code

  17. Caching is an essential architectural strategy

  18. Hi, I’m Thijs

  19. I’m @ThijsFeryn on Twitter

  20. I’m an Evangelist At

  21. I’m an Evangelist At

  22. None
  23. None
  24. Normally User Server

  25. With Varnish User Varnish Server

  26. None
  27. None
  28. ✓ Page cache ✓ Dynamic page cache ✓ Render cache

    ✓ BigPipe ✓ BigPipe sessionless
  29. Install & configure

  30. https://packagecloud.io/varnishcache/varnish60 https://packagecloud.io/varnishcache/varnish5 https://packagecloud.io/varnishcache/varnish41

  31. $ curl -s https://packagecloud.io/install/repositories/ varnishcache/varnish6/script.deb.sh | sudo bash $ apt-get

    install varnish Debian & Ubuntu
  32. $ apt-cache policy varnish varnish: Installed: 6.0.0-1~stretch Candidate: 6.0.0-1~stretch Version

    table: *** 6.0.0-1~stretch 500 500 https://packagecloud.io/varnishcache/varnish60/debian stretch/main amd64 Packages 100 /var/lib/dpkg/status amd64 Packages 5.0.0-7+deb9u1 500 500 http://deb.debian.org/debian stretch/main amd64 Packages 500 http://security.debian.org stretch/updates/main amd64 Packages
  33. $ apt-get install varnish=6.0.0-1~stretch

  34. $ curl -s https://packagecloud.io/install/repositories/ varnishcache/varnish60/script.rpm.sh | sudo bash $ yum

    install varnish RHEL & CentOS
  35. Config file

  36. -a: binding address & port -T: admin binding -f: VCL

    file -S: secret file -s: storage -j: jailing -l: shared memory log size -t: default TTL -p: runtime parameters Options
  37. DAEMON_OPTS="-j unix,user=www-data \ -a main=0000:80 \ -a proxy=0.0.0.0:81,PROXY \ -T

    localhost:6082 \ -f /etc/varnish/default.vcl \ -S /etc/varnish/secret \ -l 100m,10m \ -t 60 \ -p feature=+esi_disable_xml_check \ -p feature=+http2 \ -p connect_timeout=20s \ -p first_byte_timeout=100s \ -p between_bytes_timeout=5s \ -s malloc,3g"
  38. The backend

  39. Other port Other IP Other server

  40. ✓In VCL file ✓In config file using "-b" Link backend

    to Varnish
  41. DAEMON_OPTS="-j unix,user=www-data \ -a main=0.0.0.0:80 \ -a proxy=0.0.0.0:81,PROXY \ -T

    localhost:6082 \ -b 127.0.0.1:8080 \ -S /etc/varnish/secret \ -s malloc,3g" Can't have -f In config file
  42. vcl 4.0;
 
 backend default {
 .host = "127.0.0.1";
 .port

    = "8080";
 } In VCL file Minimal VCL
  43. What about TLS/SSL?

  44. ✓HAProxy ✓Nginx ✓Pound ✓Hitch Terminate TLS/SSL

  45. HAProxy Varnish Nginx HTTP & HTTPS HTTP HTTP Certificates go

    here Public
  46. How do you know if it was HTTP or HTTPS?

  47. X-Forwarded-Proto: https X-Forwarded-Proto: http

  48. What’s the real IP?

  49. X-Forwarded-For

  50. Nginx Public 172.18.0.1 Client IP: 172.18.0.1 X-Forwarded-For:

  51. Varnish 172.18.0.8 Nginx Public 172.18.0.1 Client IP: 172.18.0.8 X-Forwarded-For: 172.18.0.1

  52. HAProxy 172.18.0.3 Varnish 172.18.0.8 Nginx Public 172.18.0.1 Client IP: 172.18.0.8

    X-Forwarded-For: 172.18.0.3
  53. PROXY Protocol

  54. Add original IP as TCP preamble

  55. DAEMON_OPTS="-j unix,user=www-data \ -a :80 \ -a :81,PROXY \ -T

    localhost:6082 \ -f /etc/varnish/default.vcl \ -S /etc/varnish/secret \ -l 100m,10m \ -t 60 \ -p feature=+esi_disable_xml_check \ -p connect_timeout=20s \ -p first_byte_timeout=100s \ -p between_bytes_timeout=5s \ -s malloc,3g"
  56. HAProxy 172.18.0.3 Varnish 172.18.0.8 Nginx Public 172.18.0.1 Client IP: 172.18.0.8

    X-Forwarded-For: 172.18.0.1
  57. None
  58. <?php $settings['reverse_proxy'] = TRUE; $settings['reverse_proxy_addresses'] = array('127.0.0.1'); Drupal\Core\StackMiddleware\ReverseProxyMiddleware

  59. // Initialize proxy settings. if ($settings->get('reverse_proxy', FALSE)) { $ip_header =

    $settings->get('reverse_proxy_header', 'X_FORWARDED_FOR'); $request::setTrustedHeaderName($request::HEADER_X_FORWARDED_FOR, $ip_header); $proto_header = $settings->get('reverse_proxy_proto_header', 'X_FORWARDED_PROTO'); $request::setTrustedHeaderName($request::HEADER_X_FORWARDED_PROTO, $proto_header); $host_header = $settings->get('reverse_proxy_host_header', 'X_FORWARDED_HOST'); $request::setTrustedHeaderName($request::HEADER_X_FORWARDED_HOST, $host_header); $port_header = $settings->get('reverse_proxy_port_header', 'X_FORWARDED_PORT'); $request::setTrustedHeaderName($request::HEADER_X_FORWARDED_PORT, $port_header); $forwarded_header = $settings->get('reverse_proxy_forwarded_header', 'FORWARDED'); $request::setTrustedHeaderName($request::HEADER_FORWARDED, $forwarded_header); $proxies = $settings->get('reverse_proxy_addresses', []); if (count($proxies) > 0) { $request::setTrustedProxies($proxies, Request::HEADER_X_FORWARDED_ALL | Request::HEADER_FORWARDED); } } Drupal\Core\StackMiddleware\ReverseProxyMiddleware
  60. There are rules

  61. ✓Idempotence ✓State ✓Expiration ✓Conditional requests ✓Cache variations Varnish speaks HTTP

  62. Idempotence Execute multiple times Result doesn't change

  63. ✓ GET ✓ HEAD - POST - PUT - DELETE

    - PATCH Idempotence Result changes Result doesn't change Don't cache
  64. State

  65. State ~ user specific data Cookies Auth headers

  66. About cookies

  67. ✓ Request header ✓ Sent by client (~browser) ✓ Sent

    on every request ✓ Describes state ✓ Is not cached ✓ 3rd party tracking cookies vs own cookies About cookies Cookie: key=value;key2=value2
  68. ✓ Response header ✓ Sent by backend server ✓ Only

    when backend is called ✓ Changes state ✓ Is not cached ✓ Blacklisted for 120s (by default) About cookies Set-Cookie: key=another_value
  69. Time To Live

  70. 1.VCL 2.s-maxage 3.max-age 4.expires 5.Default value 120s TTL Order

  71. Cache-Control: public, max-age=1000, s-maxage=3600

  72. Use TTL not to cache Cache-Control: max-age=0 Cache-Control: s-maxage=0 Cache-Control:

    private Cache-Control: no-cache Cache-Control: no-store Expires: Fri, 1 Jan 1971 00:00:00 GMT
  73. Age Age: 10 How old is the cached object?

  74. Real cache duration max-age - Age s-maxage - Age

  75. Don’t set the Age header yourself!

  76. Conditional requests

  77. Only fetch payload that has changed

  78. Otherwise: HTTP/1.1 304 Not Modified

  79. ✓ Conserve bandwidth ✓ Reduce load on the backend when

    revalidating Conditional requests
  80. Conditional requests HTTP/1.1 200 OK Host: localhost Etag: 7c9d70604c6061da9bb9377d3f00eb27 Content-type:

    text/html; charset=UTF-8 Hello world output GET / HTTP/1.1 Host: localhost User-Agent: curl/7.48.0
  81. Conditional requests HTTP/1.0 304 Not Modified Host: localhost Etag: 7c9d70604c6061da9bb9377d3f00eb27

    GET / HTTP/1.1 Host: localhost User-Agent: curl/7.48.0 If-None-Match: 7c9d70604c6061da9bb9377d3f00eb27
  82. Conditional requests HTTP/1.1 200 OK Host: localhost Last-Modified: Fri, 22

    Jul 2016 10:11:16 GMT Content-type: text/html; charset=UTF-8 Hello world output GET / HTTP/1.1 Host: localhost User-Agent: curl/7.48.0
  83. Conditional requests HTTP/1.0 304 Not Modified Host: localhost Last-Modified: Fri,

    22 Jul 2016 10:11:16 GMT GET / HTTP/1.1 Host: localhost User-Agent: curl/7.48.0 If-Last-Modified: Fri, 22 Jul 2016 10:11:16 GMT
  84. Store etag or modification date

  85. Validate early on

  86. Exit quickly

  87. None
  88. $last_modified = $response->getLastModified(); if ($last_modified) { // See if the

    client has provided the required HTTP headers. $if_modified_since = $request->server->has('HTTP_IF_MODIFIED_SINCE') ? strtotime($request->server- >get('HTTP_IF_MODIFIED_SINCE')) : FALSE; $if_none_match = $request->server->has('HTTP_IF_NONE_MATCH') ? stripslashes($request->server- >get('HTTP_IF_NONE_MATCH')) : FALSE; if ($if_modified_since && $if_none_match // etag must match. && $if_none_match == $response->getEtag() // if-modified-since must match. && $if_modified_since == $last_modified->getTimestamp()) { $response->setStatusCode(304); $response->setContent(NULL); // In the case of a 304 response, certain headers must be sent, and the // remaining may not (see RFC 2616, section 10.3.5). foreach (array_keys($response->headers->all()) as $name) { if (!in_array($name, ['content-location', 'expires', 'cache-control', 'vary'])) { $response->headers->remove($name); } } } } Drupal\page_cache\StackMiddleware\PageCache
  89. Varnish can revalidate aynchronously

  90. In both directions User Varnish Server 304 Not Modified 304

    Not Modified
  91. And serve stale data while that happens

  92. Grace mode

  93. Effective TTL = TTL + grace

  94. Cache-Control: public, max-age=100, s-maxage=3600, stale-while-revalidate=7200 Stale-While-Revalidate Set grace mode

  95. Variations

  96. Cache is not the same for everyone

  97. ✓ URL ✓ Hostname ✓ IP if hostname is not

    set ✓ Vary header Basic variations
  98. Vary header Vary: Accept-Encoding Vary: Accept-Language Vary: Cookie Watch out!

  99. The flow

  100. None
  101. None
  102. Varnish Configuration Language

  103. DSL compiled and linked as shared object

  104. /etc/varnish/default.vcl

  105. Hooks & subroutines

  106. ✓vcl_recv: receive request ✓vcl_hash: compose cache key ✓vcl_miss: not found

    in cache ✓vcl_hit: found in cache ✓vcl_pass: don’t store in cache ✓vcl_pipe: bypass cache ✓vcl_backend_fetch: connect to backend ✓vcl_backend_response: response from backend ✓vcl_backend_error: backend fetch failed
  107. ✓vcl_purge: after successful purge ✓vcl_synth: send synthetic output ✓vcl_deliver: return

    data to client ✓vcl_init: initialize VMODs ✓vcl_fini: discard VMODs ✓vcl_fail: stop execution
  108. Actions

  109. ✓ hash: lookup in cache ✓ pass: don't cache ✓

    synth: synthetic HTML output ✓ pipe: bypass cache ✓ purge: remove from cache VCL_RECV
  110. ✓ synth: synthetic HTML output ✓ pipe: bypass cache VCL_PIPE

  111. ✓ fetch: fetch data from backend, don't cache ✓ restart:

    restart transaction ✓ synth: synthetic HTML output VCL_PASS
  112. ✓ deliver: send cached object ✓ miss: synchronous refresh despite

    hit ✓ pass: fetch data from backend despite hit, don't cache ✓ restart: restart transaction ✓ synth: synthetic HTML output VCL_HIT
  113. ✓ fetch: fetch data from backend ✓ pass: fetch data

    from backend, don't cache ✓ restart: restart transaction ✓ synth: synthetic HTML output VCL_MISS
  114. ✓ lookup: look for cached object by using hash key

    VCL_HASH
  115. ✓ restart: restart transaction ✓ synth: synthetic HTML output VCL_PURGE

  116. ✓ deliver: deliver object to client ✓ restart: restart transaction

    ✓ synth: synthetic HTML output VCL_DELIVER
  117. ✓ deliver: deliver synthetic output to client ✓ restart: restart

    transaction VCL_SYNTH
  118. ✓ fetch: fetch object from backend ✓ abandon: abandon request

    and send HTTP 503 error VCL_BACKEND_FETCH
  119. ✓ deliver: send fetched data to client ✓ abandon: abandon

    request and send HTTP 503 error ✓ retry: retry backend request VCL_BACKEND_RESPONSE
  120. ✓ deliver: send fetched data to client ✓ retry: retry

    backend request VCL_BACKEND_ERROR
  121. Typical flows

  122. ✓ vcl_recv: hash ✓ vcl_hash: lookup ✓ vcl_miss: fetch ✓

    vcl_backend_request: fetch ✓ vcl_backend_response: deliver ✓ vcl_deliver: deliver MISS
  123. ✓ vcl_recv: hash ✓ vcl_hash: lookup ✓ vcl_hit: deliver ✓

    vcl_deliver: deliver HIT
  124. ✓ vcl_recv: pass ✓ vcl_pass: fetch ✓ vcl_backend_request: fetch ✓

    vcl_backend_response: deliver ✓ vcl_deliver: deliver PASS
  125. Objects

  126. ✓ req: incoming request object ✓ req_top: top level esi

    request ✓ bereq: request object to send to backend ✓ beresp: backend response ✓ resp: response to send back to client ✓ obj: cached object ✓ client: client information ✓ server: server information ✓ local: local TCP information ✓ remote: remote TCP information ✓ storage: storage information VCL Objects
  127. Variables

  128. ✓ req.url ✓ req.http.host ✓ req.http.user-agent ✓ req.backend_hint ✓ req.method

    ✓ … req variables
  129. ✓ bereq.backend ✓ bereq.http.user-agent ✓ bereq.method ✓ bereq.url ✓ …

    bereq variables
  130. ✓ beresp.age ✓ beresp.backend.ip ✓ beresp.backend.name ✓ beresp.do_esi ✓ beresp.grace

    ✓ beresp.keep ✓ beresp.http.set-cookie ✓ beresp.ttl ✓ beresp.status ✓ beresp.uncacheable beresp variables
  131. ✓ client.ip ✓ client.identity client variables local variables ✓ local.ip

    remote variables ✓ remote.ip
  132. ✓ obj.age ✓ obj.grace ✓ obj.hits ✓ obj.http.cache-control ✓ obj.reason

    ✓ obj.status ✓ obj.ttl object variables
  133. ✓ resp.http.user-agent ✓ resp.is_streaming ✓ resp.reason ✓ resp.status resp variables

  134. Default behaviour

  135. vcl 4.0; sub vcl_recv { if (req.method != "GET" &&

    req.method != "HEAD" && req.method != "PUT" && req.method != "POST" && req.method != "TRACE" && req.method != "OPTIONS" && req.method != “PATCH" && req.method != "DELETE") { return (pipe); } if (req.method != "GET" && req.method != "HEAD") { return (pass); } if (req.http.Authorization || req.http.Cookie) { return (pass); } return (hash); } Idempotence State Action Receive request
  136. sub vcl_hash { hash_data(req.url); if (req.http.host) { hash_data(req.http.host); } else

    { hash_data(server.ip); } return (lookup); } Lookup in cache Variations Action
  137. sub vcl_purge { return (synth(200, "Purged")); } sub vcl_hit {

    if (obj.ttl >= 0s) { return (deliver); } if (obj.ttl + obj.grace > 0s) { return (deliver); } return (miss); } sub vcl_miss { return (fetch); } sub vcl_deliver { return (deliver); } Remove from cache Found in cache Not found in cache Return HTTP response to client
  138. sub vcl_synth { set resp.http.Content-Type = "text/html; charset=utf-8"; set resp.http.Retry-After

    = "5"; synthetic( {"<!DOCTYPE html> <html> <head> <title>"} + resp.status + " " + resp.reason + {"</title> </head> <body> <h1>Error "} + resp.status + " " + resp.reason + {"</h1> <p>"} + resp.reason + {"</p> <h3>Guru Meditation:</h3> <p>XID: "} + req.xid + {"</p> <hr> <p>Varnish cache server</p> </body> </html> "} ); return (deliver); } Send custom HTML
  139. sub vcl_backend_fetch { return (fetch); } sub vcl_backend_response { if

    (bereq.uncacheable) { return (deliver); } else if (beresp.ttl <= 0s || beresp.http.Set-Cookie || beresp.http.Surrogate-control ~ "no-store" || (!beresp.http.Surrogate-Control && beresp.http.Cache-Control ~ "no-cache|no-store|private") || beresp.http.Vary == "*") { set beresp.ttl = 120s; set beresp.uncacheable = true; } return (deliver); } Send backend request Receive backend response TTL State Receive backend response
  140. sub vcl_backend_error { set beresp.http.Content-Type = "text/html; charset=utf-8"; set beresp.http.Retry-After

    = "5"; synthetic( {"<!DOCTYPE html> <html> <head> <title>"} + beresp.status + " " + beresp.reason + {"</title> </head> <body> <h1>Error "} + beresp.status + " " + beresp.reason + {"</h1> <p>"} + beresp.reason + {"</p> <h3>Guru Meditation:</h3> <p>XID: "} + bereq.xid + {"</p> <hr> <p>Varnish cache server</p> </body> </html> "} ); return (deliver); } Send custom HTML on backend error
  141. In an ideal world

  142. HTTP best practices > custom VCL

  143. Reality sucks

  144. None
  145. None
  146. Don’t trust the end-user

  147. Cache-control ?

  148. Legacy

  149. Write VCL

  150. Normalize

  151. set req.http.Host = regsub(req.http.Host, ":[0-9]+", ""); set req.url = std.querysort(req.url);

    if (req.url ~ "(\?|&)(utm_source|utm_medium|utm_campaign|utm_content|gclid|cx|ie| cof|siteurl)=") { set req.url = regsuball(req.url, "&(utm_source|utm_medium|utm_campaign| utm_content|gclid|cx|ie|cof|siteurl)=([A-z0-9_\-\.%25]+)", ""); set req.url = regsuball(req.url, "\?(utm_source|utm_medium|utm_campaign| utm_content|gclid|cx|ie|cof|siteurl)=([A-z0-9_\-\.%25]+)", "?"); set req.url = regsub(req.url, "\?&", "?"); set req.url = regsub(req.url, "\?$", ""); } if (req.url ~ "\#") { set req.url = regsub(req.url, "\#.*$", ""); } if (req.url ~ "\?$") { set req.url = regsub(req.url, "\?$", ""); } Normalize
  152. Static assets

  153. vcl 4.0; sub vcl_recv { if (req.url ~ "^[^?]*\.(7z|avi|bmp|bz2|css|csv|doc|docx|eot|flac|flv|gif|gz|ico|jpeg| jpg|js|less|mka|mkv|mov|mp3|mp4|mpeg|mpg|odt|otf|ogg|ogm|opus|pdf|png|ppt|pptx|rar|rtf|

    svg|svgz|swf|tar|tbz|tgz|ttf|txt|txz|wav|webm|webp|woff|woff2|xls|xlsx|xml|xz|zip) (\?.*)?$") { unset req.http.Cookie; return (hash); } } sub vcl_backend_response { if (bereq.url ~ "^[^?]*\.(7z|avi|bmp|bz2|css|csv|doc|docx|eot|flac|flv|gif|gz|ico| jpeg|jpg|js|less|mka|mkv|mov|mp3|mp4|mpeg|mpg|odt|otf|ogg|ogm|opus|pdf|png|ppt|pptx| rar|rtf|svg|svgz|swf|tar|tbz|tgz|ttf|txt|txz|wav|webm|webp|woff|woff2|xls|xlsx|xml|xz| zip)(\?.*)?$") { unset beresp.http.set-cookie; } if (bereq.url ~ "^[^?]*\.(7z|avi|bz2|flac|flv|gz|mka|mkv|mov|mp3|mp4|mpeg|mpg|ogg|ogm| opus|rar|tar|tgz|tbz|txz|wav|webm|xz|zip)(\?.*)?$") { unset beresp.http.set-cookie; set beresp.do_stream = true; set beresp.do_gzip = false; } } Cache static assets
  154. Do you really want to cache static assets?

  155. Nginx or Apache can be fast enough for that

  156. vcl 4.0; import std; sub vcl_recv { if (req.url ~

    "^[^?]*\.(7z|avi|bmp|bz2|css|csv|doc|docx|eot|flac|flv| gif|gz|ico|jpeg|jpg|js|less|mka|mkv|mov|mp3|mp4|mpeg|mpg|odt|otf|ogg| ogm|opus|pdf|png|ppt|pptx|rar|rtf|svg|svgz|swf|tar|tbz|tgz|ttf|txt|txz| wav|webm|webp|woff|woff2|xls|xlsx|xml|xz|zip)(\?.*)?$") { unset req.http.Cookie; return (pass); } } Don’t cache static assets
  157. Blacklist/whitelist

  158. sub vcl_recv { if (req.url ~ "^/status\.php$" || req.url ~

    "^/update\.php$" || req.url ~ "^/admin$" || req.url ~ "^/admin/.*$" || req.url ~ "^/flag/.*$" || req.url ~ "^.*/ajax/.*$" || req.url ~ "^.*/ahah/.*$") { return (pass); } } URL blacklist
  159. sub vcl_recv { if (req.url ~ "^/some-page/?" return (hash); }

    } URL whitelist
  160. if (beresp.http.Surrogate-Control ~ "BigPipe/1.0") { set beresp.do_stream = true; set

    beresp.ttl = 0s; } Don't cache BigPipe responses
  161. Those damn cookies again!

  162. vcl 4.0; sub vcl_recv { if (req.http.Cookie) { set req.http.Cookie

    = ";" + req.http.Cookie; set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";"); set req.http.Cookie = regsuball(req.http.Cookie, ";(SESS[a-z0-9]+|SSESS[a-z0-9]+|NO_CACHE)=", "; \1="); set req.http.Cookie = regsuball(req.http.Cookie, ";[^ ][^;]*", ""); set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", ""); if (req.http.Cookie == "") { unset req.http.Cookie; } else { return (pass); } } } Only keep Drupal cookies
  163. sub vcl_recv { if (req.http.Cookie) { set req.http.Cookie = ";"

    + req.http.Cookie; set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";"); set req.http.Cookie = regsuball(req.http.Cookie, ";(language)=", "; \1="); set req.http.Cookie = regsuball(req.http.Cookie, ";[^ ][^;]*", ""); set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", ""); if (req.http.cookie ~ "^\s*$") { unset req.http.cookie; return(pass); } return(hash); } } sub vcl_hash { hash_data(regsub( req.http.Cookie, "^.*language=([^;]*);*.*$", "\1" )); } Language cookie cache variation
  164. sub vcl_recv { return(hash); } Cache, even with cookies

  165. sub vcl_hash { hash_data(req.http.Cookie); } Hash all cookies

  166. Block caching

  167. None
  168. Code renders single HTTP response

  169. Lowest denominator: no cache

  170. <esi:include src="/header" /> Edge Side Includes ✓Placeholder ✓Parsed by Varnish

    ✓Output is a composition of blocks ✓State per block ✓TTL per block
  171. sub vcl_recv { set req.http.Surrogate-Capability = "key=ESI/1.0"; } sub vcl_backend_response

    { if (beresp.http.Surrogate-Control ~ "ESI/1.0") { unset beresp.http.Surrogate-Control; set beresp.do_esi = true; } } Edge Side Includes
  172. <?php header("Cache-Control: public,must-revalidate,s-maxage=10"); echo "Date in the ESI tag: ".date('Y-m-d

    H:i:s').'<br />'; <?php header("Cache-Control: no-store"); header(“Surrogate-Control: content='ESI/1.0'"); echo '<esi:include src="/esi.php" />'.PHP_EOL; echo "Date in the main page: ".date('Y-m-d H:i:s').'<br />'; Main page ESI frame: esi.php Cached for 10 seconds Not cached
  173. ESI_xmlerror No ESI processing, first char not '<'. (See feature

    esi_disable_xml_check) Expects HTML/ XML tags
  174. -p feature=+esi_disable_xml_check Add as startup option

  175. req_top Get information about parent request in an ESI call

  176. vcl 4.0; backend default { .host = "nginx"; .port =

    "80"; } sub vcl_recv { if (req.esi_level > 0) { set req.http.x-parent-url = req_top.url; } } sub vcl_backend_response { if (beresp.http.Surrogate-Control ~ "ESI/1.0") { unset beresp.http.Surrogate-Control; set beresp.do_esi = true; } } Get parent URL
  177. ESI vs AJAX

  178. ✓ Server-side ✓ Standardized ✓ Processed on the “edge”, no

    in the browser ✓ Generally faster Edge-Side Includes - Sequential - One fails, all fail - Limited implementation in Varnish - Not that common
  179. ✓ Client-side ✓ Common knowledge ✓ Parallel processing ✓ Graceful

    degradation AJAX - Processed by the browser - Extra roundtrips - Somewhat slower
  180. Choose wisely

  181. None
  182. Auto-placeholdering

  183. BigPipe

  184. <span data-big-pipe-placeholder- id="callback=Drupal%5CCore%5CRender%5CElem ent%5CStatusMessages%3A%3ArenderMessages&a mp;args%5B0%5D&amp;token=_HAdUpwWmet0TOTe2 PSiJuMntExoshbm1kh2wQzzzAA"></span>

  185. <script type="application/vnd.drupal-ajax" data-big-pipe- replacement-for-placeholder-with- id="callback=Drupal%5CCore%5CRender%5CElement%5CStatusMessages%3A%3A renderMessages&amp;args%5B0%5D&amp;token=_HAdUpwWmet0TOTe2PSiJuMntEx oshbm1kh2wQzzzAA"> [{"command":"insert","method":"replaceWith","selector":"[data-big- pipe-placeholder- id=\u0022callback=Drupal%5CCore%5CRender%5CElement%5CStatusMessages%

    3A%3ArenderMessages\u0026args%5B0%5D\u0026token=_HAdUpwWmet0TOTe2PSi JuMntExoshbm1kh2wQzzzAA\u0022]","data":"","settings":null}] </script>
  186. https://github.com/ThijsFeryn/drupal8_esi_placeholders

  187. services: esi: class: Symfony\Component\HttpKernel\HttpCache\Esi esi_placeholders.esi_subscriber: class: Drupal\esi_placeholders\EventSubscriber\EsiSubscriber arguments: ['@esi'] tags:

    - { name: event_subscriber } esi_placeholders.placeholder_strategy.esi: class: Drupal\esi_placeholders\Render\Placeholder\EsiStrategy arguments: ['@request_stack','@esi'] tags: - { name: placeholder_strategy, priority: 0 }
  188. esi_placeholders.esi_block_rendering: path: '/esi/block' defaults: _controller: '\Drupal\esi_placeholders\Controller\EsiController:returnEsiBlo ckContent' _title: 'ESI content'

    requirements: _permission: 'access content'
  189. <?php namespace Drupal\esi_placeholders\Render\Placeholder; use Drupal\big_pipe\Render\Placeholder\BigPipeStrategy; use Drupal\Core\Render\Markup; use Symfony\Component\HttpFoundation\RequestStack; use

    Symfony\Component\HttpKernel\HttpCache\Esi; class EsiStrategy extends BigPipeStrategy { /** * @var RequestStack */ protected $requestStack; /** * @var Esi */ protected $esi; /** * EsiStrategy constructor. * @param RequestStack $request_stack * @param Esi $esi */ public function __construct(RequestStack $request_stack, Esi $esi) { $this->requestStack = $request_stack; $this->esi = $esi; } /**
  190. /** * @param array $placeholders * @return array */ public

    function processPlaceholders(array $placeholders) { $request = $this->requestStack->getCurrentRequest(); $overridenPlaceHolder = []; foreach ($placeholders as $placeholder => $placeholder_elements) { if (isset($placeholder_elements['#lazy_builder']) && $this->esi->hasSurrogateCapability($request)) { $overridenPlaceHolder[$placeholder] = [ '#markup' => Markup::create( $this->esi->renderIncludeTag( '/esi/block/?'. $this->generateBigPipePlaceholderId($placeholder,$placeholder_elements), null, false ) ) ]; } } return $overridenPlaceHolder; } }
  191. <?php namespace Drupal\esi_placeholders\Controller; use Drupal\Core\Cache\CacheableMetadata; use Drupal\Core\Cache\CacheableResponse; use Drupal\Core\Controller\ControllerBase; use

    Symfony\Component\HttpFoundation\Request; class EsiController extends ControllerBase { public function returnEsiBlockContent(Request $request) { $build = [ 'esiBlockContent' => [ '#lazy_builder' => [ $request->get('callback'), $request->get('args'), ] ] ]; $output = \Drupal::service('renderer')->renderRoot($build); $response = new CacheableResponse($output); $response->addCacheableDependency(CacheableMetadata::createFromRenderArray($build)); return $response; } }
  192. <?php namespace Drupal\esi_placeholders\EventSubscriber; use Symfony\Component\HttpKernel\Event\FilterResponseEvent; use Symfony\Component\HttpKernel\HttpCache\Esi; use Symfony\Component\HttpKernel\KernelEvents; use

    Symfony\Component\EventDispatcher\EventSubscriberInterface; class EsiSubscriber implements EventSubscriberInterface { /** * @var Symfony\Component\HttpKernel\HttpCache\Esi */ protected $esi; /** * @param Symfony\Component\HttpKernel\HttpCache\Esi $esi */ public function __construct(Esi $esi) { $this->esi = $esi; } /** * @param FilterResponseEvent $event * @return \Symfony\Component\HttpFoundation\Response */
  193. /** * @param FilterResponseEvent $event * @return \Symfony\Component\HttpFoundation\Response */ public

    function onRespond(FilterResponseEvent $event) { $request = $event->getRequest(); $response = $event->getResponse(); if($this->esi->hasSurrogateCapability($request)){ $this->esi->addSurrogateControl($response); return $response; } } /** * {@inheritdoc} */ public static function getSubscribedEvents() { $events[KernelEvents::RESPONSE][] = ['onRespond', -10000]; return $events; } }
  194. https://github.com/ThijsFeryn/drupal8_esi_placeholders

  195. Breaking news isn't breaking

  196. Purging

  197. acl purgers { "localhost"; "127.0.0.1"; "::1"; } sub vcl_recv {

    if (req.method == "PURGE") { if (client.ip !~ purgers) { return (synth(405, "Method not allowed")); } return (purge); } } Purging
  198. Purging curl -XPURGE "http://example.com/products" Immediately remove from memory

  199. acl purge { "localhost"; "127.0.0.1"; "::1"; } sub vcl_recv {

    if (req.method == "PURGE") { if (client.ip !~ purgers) { return (synth(405, "Method not allowed")); } if(req.http.x-purge-regex) { ban("req.http.host == " + req.http.host + " && req.url ~ " + req.http.x-purge-regex); } else { ban("req.http.host == " + req.http.host + " && req.url == " + req.url); } return (synth(200, "Purged")); } } Banning
  200. Banning curl -XPURGE "http://example.com/products" curl -XPURGE -H "x-purge-regex:/products" "http://example.com" Add

    to ban list, remove on next request Remove patterns via “X-PURGE-REGEX”
  201. Lurker-friendly bans

  202. Ban lurker Object User Varnish Server Sends HTTP response Response

    stored in object Sends BAN to Varnish Ban lurker thread Ban list Reads ban list Removes object ban req.http.host == localhost && req.url ~ /products
  203. Ban lurker ban req.http.host == localhost && req.url ~ /products

    Lurker can’t match request info Lurker can only match what’s in the object Next visitor triggers cache remove
  204. acl purge { "localhost"; "127.0.0.1"; "::1"; } sub vcl_recv {

    if (req.method == "PURGE") { if (client.ip !~ purgers) { return (synth(405, "Method not allowed")); } if(req.http.x-purge-regex) { ban("obj.http.x-host == " + req.http.host + " && obj.http.x-url ~ " + req.http.x-purge-regex); } else { ban("obj.http.host == " + req.http.host + " && obj.http.x-url == " + req.url); } return (synth(200, "Purged")); } } sub vcl_backend_response { set beresp.http.x-url = bereq.url; set beresp.http.x-host = bereq.http.host; } sub vcl_deliver { unset resp.http.x-url; unset resp.http.x-host; } Lurker-friendly bans Store request info in response object
  205. Lurker-friendly bans ban obj.http.x-host == localhost && obj.http.x-url ~ /products

    Lurker can match response info Ban lurker removes item from cache async
  206. Banning through Varnishadm

  207. varnishadm> ban obj.http.x-host == localhost && obj.http.x-url ~ /products Varnishadm

    banning
  208. Banning through socket

  209. Varnishadm is a binary on top of the socket

  210. Varnishadm uses the secret file to authenticate automatically

  211. $ telnet varnish 6082 Connected to localhost. Escape character is

    '^]'. 107 59 cohvooigdtqvkpwewhdxkqiwkfkpwsly Authentication required. auth 5a9c5722f31cc3c92f0e4616571624df7bddde2f8e42aaffe795dc80fb8c91dd 200 240 ----------------------------- Varnish Cache CLI 1.0 ----------------------------- Linux,4.9.49-moby,x86_64,-junix,-smalloc,-smalloc,-hcritbit varnish-5.2.0 revision 4c4875cbf Type 'help' for command list. Type 'quit' to close CLI session. ban obj.http.x-host == localhost && obj.http.x-url ~ /products 200 0
  212. <?php $challenge = $argv[1]; $secret = trim(fgets(STDIN)); $pack = $challenge

    . "\x0A" . $secret . "\x0A" . $challenge . "\x0A"; $key = hash('sha256', $pack); echo $key.PHP_EOL; Use secret & process challenge cohvooigdtqvkpwewhdxkqiwkfkpwsly 5a9c5722f31cc3c92f0e4616571624df7bddde2f8e42aaffe795dc80fb8c91dd E29F6DE6-3803-449E-8A01-AA537A8715B1
  213. $ telnet varnish 6082 Connected to localhost. Escape character is

    '^]'. 107 59 cohvooigdtqvkpwewhdxkqiwkfkpwsly Authentication required. auth 5a9c5722f31cc3c92f0e4616571624df7bddde2f8e42aaffe795dc80fb8c91dd 200 240 ----------------------------- Varnish Cache CLI 1.0 ----------------------------- Linux,4.9.49-moby,x86_64,-junix,-smalloc,-smalloc,-hcritbit varnish-5.2.0 revision 4c4875cbf Type 'help' for command list. Type 'quit' to close CLI session. ban obj.http.x-host == localhost && obj.http.x-url ~ /products 200 0
  214. Secure your access the the admin socket

  215. DAEMON_OPTS="-j unix,user=www-data \ -a :80 \ -a :81,PROXY \ -T

    localhost:6082 \ -f /etc/varnish/default.vcl \ -S /etc/varnish/secret \ -l 100m,10m \ -t 60 \ -p feature=+esi_disable_xml_check \ -p connect_timeout=20s \ -p first_byte_timeout=100s \ -p between_bytes_timeout=5s \ -s malloc,3g"
  216. None
  217. ✓purge ✓purge_purger_http Required modules

  218. None
  219. None
  220. None
  221. None
  222. # Only allow BAN requests from IP addresses in the

    'purge' ACL. if (req.method == "BAN") { # Same ACL check as above: if (!client.ip ~ purge) { return (synth(403, "Not allowed.")); } if (req.http.Purge-Cache-Tags) { ban("obj.http.Purge-Cache-Tags ~ " + req.http.Purge-Cache-Tags); } else { return (synth(403, "Purge-Cache-Tags header missing.")); } # Throw a synthetic page so the request won't go to the backend. return (synth(200, "Ban added.")); }
  223. acl purge { "127.0.0.1"; }

  224. Purge-Cache-Tags: block:the_date_time block_view config:block.block.bartik_account_menu config:block.block.bartik_branding config:block.block.bartik_breadcrumbs config:block.block.bartik_content config:block.block.bartik_footer config:block.block.bartik_help config:block.block.bartik_local_actions

    config:block.block.bartik_local_tasks config:block.block.bartik_main_menu config:block.block.bartik_messages config:block.block.bartik_page_title config:block.block.bartik_powered config:block.block.bartik_search config:block.block.bartik_tools config:block.block.thedateandtimeblock config:block_list config:color.theme.bartik config:filter.format.basic_html config:search.settings config:system.menu.account config:system.menu.footer config:system.menu.main config:system.menu.tools config:system.site config:user.role.anonymous config:views.view.frontpage http_response node:1 node:2 node_list node_view rendered user:1
  225. https://feryn.eu https://twitter.com/ThijsFeryn https://instagram.com/ThijsFeryn

  226. None
  227. None
  228. sub vcl_backend_response { set beresp.grace = 6h; } Grace mode

    Monitoring & logging
  229. Varnishstat Realtime statistics

  230. None
  231. usage: varnishstat [-1lV] [-f field] [-t seconds|<off>] [-n varnish_name] [-N

    filename] -1 # Print the statistics to stdout. -f field # Field inclusion glob # If it starts with '^' it is used as an exclusion list. -l # Lists the available fields to use with the -f option. -n varnish_name # The varnishd instance to get logs from. -N filename # Filename of a stale VSM instance. -t seconds|<off> # Timeout before returning error on initial VSM connection. -V # Display the version number and exit. -x # Print statistics to stdout as XML. -j # Print statistics to stdout as JSON. Varnishstat usage
  232. ~# varnishstat -f MAIN.cache_hit -1 MAIN.cache_hit 13049135 5.39 Cache hits

    Varnishstat usage ~# varnishstat -f MAIN.cache_hit -j -1 { "timestamp": "2016-06-14T16:10:32", "MAIN.cache_hit": { "description": "Cache hits", "type": "MAIN", "flag": "c", "format": "i", "value": 13050992 } }
  233. Varnishstat usage ~# varnishstat -f MAIN.n_object -f MAIN.n_lru_nuked -j {

    "timestamp": "2016-06-14T16:14:49", "MAIN.n_object": { "description": "object structs made", "type": "MAIN", "flag": "g", "format": "i", "value": 46295 }, "MAIN.n_lru_nuked": { "description": "Number of LRU nuked objects", "type": "MAIN", "flag": "g", "format": "i", "value": 0 } }
  234. varnishstat -f MAIN.cache*

  235. ✓ Session ✓ Client ✓ Uptime ✓ Hit/miss ✓ Backend

    ✓ Fetch ✓ Threading ✓ Cache objects ✓ Memory ✓ Invalidation Varnishstat counters
  236. VSL

  237. Varnish Shared memory Logging

  238. ✓ In-memory logs ✓ Generated by varnishd ✓ 81 MB

    by default ✓ Customize with “-l” setting ✓ Varnishlog command ✓ Varnishtop command VSL
  239. * << Request >> 10973258 - Begin req 10973257 rxreq

    - Timestamp Start: 1501507281.942533 0.000000 0.000000 - Timestamp Req: 1501507281.942533 0.000000 0.000000 - ReqStart 127.0.0.1 59753 - ReqMethod GET - ReqURL / - ReqProtocol HTTP/1.1 - ReqHeader Host: feryn.eu
  240. Transactions

  241. ✓ Items of work ✓ Identified by VXID ✓ 2

    kinds: ✓ Sessions ✓ Requests Transactions
  242. ✓ Identifies TCP connection ✓ Contains multiple requests Transactions ✓

    Client request ✓ Backend request ✓ ESI subrequest Session Request
  243. None
  244. ✓ VXID (default) ✓ Session ✓ Request ✓ Raw Transactions

    grouping
  245. Example composition that will be monitored

  246. varnishlog -i Begin,ReqUrl,Link,BereqURL

  247. * << BeReq >> 98318 - Begin bereq 98317 fetch

    - BereqURL / * << BeReq >> 98320 - Begin bereq 98319 fetch - BereqURL /header * << Request >> 98319 - Begin req 98317 esi - ReqURL /header - Link bereq 98320 fetch * << BeReq >> 98322 - Begin bereq 98321 fetch - BereqURL /nav * << Request >> 98321 - Begin req 98317 esi - ReqURL /nav - Link bereq 98322 fetch * << Request >> 98317 - Begin req 98316 rxreq - ReqURL / - Link bereq 98318 fetch - Link req 98319 esi - Link req 98321 esi * << BeReq >> 98324 - Begin bereq 98323 fetch - BereqURL /footer * << Request >> 98323 - Begin req 98316 rxreq - ReqURL /footer - Link bereq 98324 fetch * << Session >> 98316 - Begin sess 0 HTTP/1 - Link req 98317 rxreq - Link req 98323 rxreq
  248. varnishlog -i Begin,ReqUrl,Link,BereqURL -g session

  249. * << Session >> 14 - Begin sess 0 HTTP/1

    - Link req 65539 rxreq - Link req 65545 rxreq ** << Request >> 65539 -- Begin req 14 rxreq -- ReqURL / -- Link bereq 65540 fetch -- Link req 65541 esi -- Link req 65543 esi ** << Request >> 65545 -- Begin req 14 rxreq -- ReqURL /footer -- Link bereq 65546 fetch *** << BeReq >> 65540 --- Begin bereq 65539 fetch --- BereqURL / *** << Request >> 65541 --- Begin req 65539 esi --- ReqURL /header --- Link bereq 65542 fetch *** << Request >> 65543 --- Begin req 65539 esi --- ReqURL /nav --- Link bereq 65544 fetch *** << BeReq >> 65546 --- Begin bereq 65545 fetch --- BereqURL /footer **** << BeReq >> 65542 ---- Begin bereq 65541 fetch ---- BereqURL /header **** << BeReq >> 65544 ---- Begin bereq 65543 fetch ---- BereqURL /nav
  250. None
  251. Tags

  252. Request tags

  253. ✓ ReqMethod ✓ ReqUrl ✓ ReqProtocol ✓ ReqHeader Request tags

  254. - ReqStart 127.0.0.1 56312 - ReqMethod GET - ReqURL /

    - ReqProtocol HTTP/1.1 - ReqHeader Host: localhost - ReqHeader Connection: keep-alive - ReqHeader Upgrade-Insecure-Requests: 1 - ReqHeader User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/ 59.0.3071.115 Safari/537.36 - ReqHeader Accept: text/html,application/xhtml+xml,application/ xml;q=0.9,image/webp,image/apng,*/*;q=0.8 - ReqHeader Accept-Encoding: gzip, deflate, br - ReqHeader Accept-Language: nl,en-US;q=0.8,en;q=0.6 - ReqHeader X-Forwarded-For: 127.0.0.1
  255. Response tags

  256. ✓ RespProtocol ✓ RespStatus ✓ RespReason ✓ RespHeader Response tags

  257. - RespProtocol HTTP/1.1 - RespStatus 200 - RespReason OK -

    RespHeader Host: localhost - RespHeader Cache-Control: public, s-maxage=500 - RespHeader Date: Tue, 01 Aug 2017 08:56:44 GMT - RespHeader ETag: "c5afddc587599a72d467caca23e980bf" - RespHeader Vary: Accept-Language - RespHeader Content-Length: 3098 - RespHeader Content-Type: text/html; charset=UTF-8 - RespHeader X-Varnish: 32770 - RespHeader Age: 10
  258. Backend tags

  259. - BackendOpen 19 boot.default 127.0.0.1 8080 127.0.0.1 62552 - BackendClose

    19 boot.default
  260. Backend request tags

  261. ✓ BereqMethod ✓ BereqUrl ✓ BereqProtocol ✓ BereqHeader Backend request

    tags
  262. Backend response tags

  263. ✓ BerespProtocol ✓ BerespStatus ✓ BerespReason ✓ BerespHeader Backens response

    tags
  264. Object tags

  265. ✓ ObjProtocol ✓ ObjStatus ✓ ObjReason ✓ ObjHeader Object tags

  266. VCL tags

  267. ✓ VCL_Call ✓ VCL_Return ✓ VCL_Error ✓ VCL_Log ✓ VCL_Acl

    VCL tags
  268. * << Request >> 5 - ReqURL / - VCL_call

    RECV - VCL_return hash - VCL_call HASH - VCL_return lookup - VCL_call MISS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver ** << BeReq >> 6 -- BereqURL / -- VCL_call BACKEND_FETCH -- VCL_return fetch -- VCL_call BACKEND_RESPONSE -- VCL_return deliver
  269. * << Request >> 6 - ReqURL / - VCL_call

    RECV - ReqURL / - VCL_return hash - VCL_call HASH - VCL_return lookup - VCL_call HIT - VCL_return deliver - VCL_call DELIVER - VCL_return deliver
  270. * << Request >> 32789 - ReqURL /header - ExpBan

    98355 banned lookup ExpBan tag
  271. * << Request >> 98369 - ReqURL /footer - Hit

    65597 Hit tag varnishlog -i "ReqUrl,Hit"
  272. ** << Request >> 6 -- ReqURL /footer -- HitPass

    3 HitPass tag
  273. TTL tag

  274. %s %d %d %d %d [ %d %d %u %u

    ] | | | | | | | | | | | | | | | | | +- Max-Age from Cache-Control header | | | | | | | +---- Expires header | | | | | | +------- Date header | | | | | +---------- Age (incl Age: header value) | | | | +--------------- Reference time for TTL | | | +------------------ Keep | | +--------------------- Grace | +------------------------ TTL +--------------------------- "RFC" or "VCL" TTL tag
  275. -- TTL VCL 120 10 0 1501597242 ✓ TTL decided

    by the VCL ✓ 120 seconds cached ✓ 10 seconds grace time ✓ 0 seconds keep time ✓ Reference time: 1501597242
 (2017-08-01 14:20:42)
  276. -- RFC 500 10 -1 1501598872 1501598872 1501598872 0 500

    ✓ 500 seconds TTL (via headers) ✓ 10 seconds grace ✓ No keep value ✓ 2017-08-01 14:47:52 date, age & reference time ✓ Cache-control headers sets 500 second TTL
  277. -- RFC 500 10 -1 1501598872 1501598869 1501598872 0 500

    ✓ Don’t screw with the age header ✓ Only 497 second effective TTL ✓ Custom Age header (3 seconds off)
  278. Begin tag

  279. - Begin bereq 98317 fetch - Begin req 98317 esi

    - Begin req 98316 rxreq - Begin sess 0 HTTP/1
  280. Link tag

  281. - Link bereq 98312 fetch - Link req 98311 rxreq

    - Link req 98318 esi
  282. Timestamp tag

  283. %s: %f %f %f | | | | | |

    | +- Time since last timestamp | | +---- Time since start of work unit | +------- Absolute time of event +----------- Event label Timestamp tag
  284. * << Request >> 65539 - Timestamp Start: 1501601912.758662 0.000000

    0.000000 - Timestamp Req: 1501601912.758662 0.000000 0.000000 - Timestamp Fetch: 1501601912.806733 0.048071 0.048071 - Timestamp Process: 1501601912.806750 0.048088 0.000017 - Timestamp Resp: 1501601912.806787 0.048125 0.000037 ** << BeReq >> 65540 -- Timestamp Start: 1501601912.758753 0.000000 0.000000 -- Timestamp Bereq: 1501601912.758952 0.000199 0.000199 -- Timestamp Beresp: 1501601912.806677 0.047924 0.047725 -- Timestamp BerespBody: 1501601912.806749 0.047996 0.000072
  285. Filtering output

  286. ✓ -i: include tags ✓ -I: include tags by regex

    ✓ -x: exclude tags ✓ -X: exclude by regex Filtering output
  287. Include tags

  288. varnishlog -i ReqUrl,VCL_call,VCL_return -g session varnishlog -i "ReqUrl,VCL_*" -g session

  289. * << Session >> 252394 ** << Request >> 252395

    -- ReqURL / -- VCL_call RECV -- VCL_return hash -- VCL_call HASH -- VCL_return lookup -- VCL_call HIT -- VCL_return deliver -- VCL_call DELIVER -- VCL_return deliver *** << Request >> 252397 --- ReqURL /header --- VCL_call RECV --- VCL_return hash --- VCL_call HASH --- VCL_return lookup --- VCL_call HIT --- VCL_return deliver --- VCL_call DELIVER --- VCL_return deliver *** << Request >> 252399 --- ReqURL /nav --- VCL_call RECV --- VCL_return hash --- VCL_call HASH --- VCL_return lookup --- VCL_call HIT --- VCL_return deliver --- VCL_call DELIVER --- VCL_return deliver *** << BeReq >> 252396 --- VCL_call BACKEND_FETCH --- VCL_return fetch --- VCL_call BACKEND_RESPONSE --- VCL_return deliver **** << BeReq >> 252398 ---- VCL_call BACKEND_FETCH ---- VCL_return fetch ---- VCL_call BACKEND_RESPONSE ---- VCL_return deliver **** << BeReq >> 252400 ---- VCL_call BACKEND_FETCH ---- VCL_return fetch ---- VCL_call BACKEND_RESPONSE ---- VCL_return deliver
  290. Exclude tags

  291. varnishlog -i "Req*" -x ReqHeader,ReqUnset

  292. * << Request >> 314125 - ReqStart 127.0.0.1 64585 -

    ReqMethod GET - ReqURL / - ReqProtocol HTTP/1.1 - ReqAcct 476 0 476 311 0 311 * << Request >> 314126 - ReqStart 127.0.0.1 64585 - ReqMethod GET - ReqURL /footer - ReqProtocol HTTP/1.1 - ReqAcct 370 0 370 309 0 309
  293. Include tags by regex

  294. varnishlog -I "reqheader:Accept-Language" -i requrl

  295. * << Request >> 374378 - ReqURL / - ReqHeader

    Accept-Language: nl,en-US;q=0.8,en;q=0.6 * << Request >> 374379 - ReqURL /footer - ReqHeader Accept-Language: nl,en-US;q=0.8,en;q=0.6
  296. Exclude tags by regex

  297. * << Request >> 374384 - ReqURL /footer - RespHeader

    Host: localhost - RespHeader X-Powered-By: PHP/7.0.15 - RespHeader Cache-Control: public, s-maxage=500 - RespHeader Date: Wed, 02 Aug 2017 11:27:21 GMT - RespHeader ETag: "d47ac09f5351f8f4c97c99ef5b3d2ecd" - RespHeader Vary: Accept-Language - RespHeader Content-Length: 80 - RespHeader Content-Type: text/html; charset=UTF-8 - RespHeader X-Varnish: 374384 15367 - RespHeader Age: 334 - RespHeader Via: 1.1 varnish-v4 - RespHeader Connection: keep-alive
  298. varnishlog -i RespHeader,ReqUrl -X "RespHeader:(x|X)-"

  299. * << Request >> 374384 - ReqURL /footer - RespHeader

    Host: localhost - RespHeader Cache-Control: public, s-maxage=500 - RespHeader Date: Wed, 02 Aug 2017 11:27:21 GMT - RespHeader ETag: "d47ac09f5351f8f4c97c99ef5b3d2ecd" - RespHeader Vary: Accept-Language - RespHeader Content-Length: 80 - RespHeader Content-Type: text/html; charset=UTF-8 - RespHeader Age: 334 - RespHeader Via: 1.1 varnish-v4 - RespHeader Connection: keep-alive
  300. All-in-one

  301. varnishlog -i "RespHeader,Req*" -X "RespHeader:(x|X)-" -I "timestamp:Resp" -x reqprotocol,reqacct -g

    request
  302. * << Request >> 59383 - ReqStart 127.0.0.1 53195 -

    ReqMethod GET - ReqURL / - ReqHeader Host: localhost - ReqHeader Connection: keep-alive - ReqHeader Cache-Control: max-age=0 - ReqHeader Upgrade-Insecure-Requests: 1 - ReqHeader User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36 - ReqHeader Accept: text/ html,application/ xhtml+xml,application/xml;q=0.9,image/ webp,image/apng,*/*;q=0.8 - ReqHeader Accept-Encoding: gzip, deflate, br - ReqHeader Accept-Language: nl,en- US;q=0.8,en;q=0.6 - ReqHeader If-None-Match: W/"27f341f8e459dd35f1087c55351cacda" - ReqHeader X-Forwarded-For: 127.0.0.1 - ReqUnset Accept-Language: nl,en- US;q=0.8,en;q=0.6 - ReqHeader accept-language: nl - ReqHeader Surrogate-Capability: key=ESI/1.0 - ReqUnset Accept-Encoding: gzip, deflate, br - ReqHeader Accept-Encoding: gzip - RespHeader Host: localhost - RespHeader Cache-Control: public, s- maxage=500 - RespHeader Date: Wed, 02 Aug 2017 11:46:49 GMT - RespHeader ETag: "27f341f8e459dd35f1087c55351cacda" - RespHeader Vary: Accept-Language - RespHeader Content-Length: 3098 - RespHeader Content-Type: text/html; charset=UTF-8 - RespHeader Age: 152 - RespHeader Via: 1.1 varnish-v4 - RespHeader ETag: W/"27f341f8e459dd35f1087c55351cacda" - RespHeader Connection: keep-alive - Timestamp Resp: 1501674561.472358 0.000068 0.000020
  303. ✓ All response headers ✓ All tags that start with

    “Req” ✓ Exclude “x-“ response headers ✓ Include “response time” timestamp ✓ Exclude request protocol log lines, and the request accountancy log lines All-in-one
  304. VSL queries

  305. Filtering fields from all transactions Filtering transactions

  306. <record selection criteria> <operator> <operand> {level}taglist:record-prefix[field]

  307. ReqUrl eq ‘/‘ {level}taglist:record-prefix[field]

  308. Timestamp:Resp[2] > 1.0 {level}taglist:record-prefix[field]

  309. {2}Timestamp:Resp[2] > 1.0 {level}taglist:record-prefix[field]

  310. varnishlog -i VCL_call,VCL_return -g request -q "ReqURL eq '/'"

  311. * << Request >> 374400 - VCL_call RECV - VCL_return

    hash - VCL_call HASH - VCL_return lookup - VCL_call HIT - VCL_return deliver - VCL_call DELIVER - VCL_return deliver
  312. varnishlog -i ReqUrl -q "VCL_call eq 'MISS' or VCL_call eq

    'PASS'" varnishlog -i ReqUrl -I "Timestamp:Resp" -q "Timestamp:Resp[2] > 1.0"
  313. Other options

  314. varnishlog -n myVarnishInstance varnishlog -d varnishlog -w file varnishlog -r

    file varnishlog -A -a -w file varnishlog -i "ReqUrl,VCL_*" -D -a -A -w /var/log/varnish/custom.log - P /var/run/custom_varnishlog.pid
  315. Varnishtop

  316. Same syntax as varnishlog. Output is incremental

  317. $ varnishtop -I reqheader:Accept-Language -q "ReqUrl eq '/'" list length

    4 0.86 ReqHeader Accept-Language: en-US 0.80 ReqHeader Accept-Language: nl-NL,nl;q=0.8,en- US;q=0.6,en;q=0.4 0.54 ReqHeader Accept-Language: nl,en-US;q=0.8,en;q=0.6 0.39 ReqHeader Accept-Language: nl-BE
  318. Common Varnishlog scenarios

  319. Why didn’t Varnish serve this request from cache?

  320. Request not cacheable

  321. varnishlog -i "Req*,VCL*" -x ReqAcct,ReqStart -q "VCL_call eq 'PASS'"

  322. * << Request >> 12 - ReqMethod GET - ReqURL

    / - ReqProtocol HTTP/1.1 - ReqHeader Host: localhost - ReqHeader User-Agent: curl/7.48.0 - ReqHeader Accept: */* - ReqHeader Cookie: myCookie=bla - ReqHeader X-Forwarded-For: 127.0.0.1 - VCL_call RECV - VCL_return pass - VCL_call HASH - VCL_return lookup - VCL_call PASS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver
  323. << Request >> 32779 - ReqMethod POST - ReqURL /

    - ReqProtocol HTTP/1.1 - ReqHeader Host: localhost - ReqHeader User-Agent: curl/7.48.0 - ReqHeader Accept: */* - ReqHeader X-Forwarded-For: 127.0.0.1 - VCL_call RECV - VCL_return pass - VCL_call HASH - VCL_return lookup - VCL_call PASS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver
  324. * << Request >> 15 - ReqMethod GET - ReqURL

    / - ReqProtocol HTTP/1.1 - ReqHeader Host: localhost - ReqHeader Authorization: Basic dGhpanM6ZmVyeW4= - ReqHeader User-Agent: curl/7.48.0 - ReqHeader Accept: */* - ReqHeader X-Forwarded-For: 127.0.0.1 - VCL_call RECV - VCL_return pass - VCL_call HASH - VCL_return lookup - VCL_call PASS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver
  325. Response not cacheable

  326. varnishlog -i ReqUrl,VCL_*,Beresp*,TTL -q "HitPass" -g request

  327. * << Request >> 19010384 - ReqURL /my-url - VCL_call

    RECV - VCL_return hash - VCL_call HASH - VCL_return lookup - VCL_call PASS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver ** << BeReq >> 19010385 -- VCL_call BACKEND_FETCH -- VCL_return fetch -- BerespProtocol HTTP/1.1 -- BerespStatus 200 -- BerespReason OK -- BerespHeader Date: Thu, 03 Aug 2017 08:15:22 GMT -- BerespHeader Server: Apache/ 2.4.10 (Debian) -- BerespHeader Last-Modified: Tue, 01 Aug 2017 07:21:00 GMT -- BerespHeader ETag: "5c0d-555abfd3f422f-gzip" -- BerespHeader Vary: Accept- Encoding -- BerespHeader Content-Encoding: gzip -- BerespHeader Cache-Control: max- age=0 -- BerespHeader Expires: Thu, 03 Aug 2017 08:15:22 GMT -- BerespHeader Content-Length: 7686 -- BerespHeader Content-Type: application/json -- TTL RFC 0 10 -1 1501748123 1501748123 1501748122 1501748122 0 -- VCL_call BACKEND_RESPONSE -- TTL VCL 120 10 0 1501748123 -- VCL_return deliver
  328. * << Request >> 65551 - ReqURL /set-cookie - VCL_call

    RECV - VCL_return hash - VCL_call HASH - VCL_return lookup - VCL_call PASS - VCL_return fetch - VCL_call DELIVER - VCL_return deliver ** << BeReq >> 65552 -- VCL_call BACKEND_FETCH -- VCL_return fetch -- BerespProtocol HTTP/1.1 -- BerespStatus 200 -- BerespReason OK -- BerespHeader Cache-control: s-maxage=10 -- BerespHeader Set-Cookie: myCookie=bla -- BerespHeader Content-type: text/html; charset=UTF-8 -- BerespHeader Date: Thu, 03 Aug 2017 08:39:04 GMT -- TTL RFC 10 10 -1 1501749545 1501749545 1501749544 0 10 -- VCL_call BACKEND_RESPONSE -- TTL VCL 120 10 0 1501749545 -- VCL_return deliver
  329. https://feryn.eu https://twitter.com/ThijsFeryn https://instagram.com/ThijsFeryn

  330. None