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.

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
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
24. Normally User Server
25. With Varnish User Varnish Server
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
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
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
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
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
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
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"
217. ✓purge ✓purge_purger_http Required modules
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
228. sub vcl_backend_response { set beresp.grace = 6h; } Grace mode Monitoring & logging
229. Varnishstat Realtime statistics
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
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
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