-
Notifications
You must be signed in to change notification settings - Fork 2
Debugging Varnish
Magento is big and complicated - and can be tricky to debug. When you put a reverse caching proxy (Varnish) in front of Magento, you're adding another layer of complexity to what is already a complicated web application.
This document is intended to help developers fix issues relating to Varnish and Turpentine.
##In the beginning… If you're just getting started with Turpentine, odds are you're going to be setting it up in a development environment to test it out. At least, that's what you should be doing! We recommend doing this in discrete steps
- Install and configure your Magento site. Make sure everything is working correctly before proceeding!
- Install and configure Varnish. Set it up with a default VCL such that it will pass all requests through directly to Magento. Of course, there's no performance advantage to be had (yet) - the idea is that you can seamlessly access your Magento site via the Varnish port.
- Install and configure Turpentine - see installation.
- Test!
After installing, testing is critical. Look especially closely at any blocks that are set to cache publicly and make sure they're flushing when appropriate, and are not showing any private information. For example
- If you add items to the shopping cart, they're not visible to other users.
- Breadcrumbs work properly
- Logged-in versus logged-out changes to menus
- Pages being cached correctly - especially for requests with GET parameters (for example)
Turn on debugging in Turpentine and refresh the caches. You should now see varnish related headers on each request. You should also see messages in the log. Remember that by default, a user's first cache is passed through to Magento, in order to receive a valid session cookie - as a result, the first time you request a page, you will not see Turpentine related messages in the source code or logs.
Go to a page. If it's not the very first request to the site, you should be able to see places where ESI includes are being used (assuming you're using ESI includes), shown by comments like this in the page source (if debugging is not turned on):
<!-- ESI START DUMMY COMMENT [] -->
<!-- ESI URL DUMMY COMMENT -->
Because Turpentine adds support for a cookie called varnish_bypass you can manually set this cookie in your browsing session, and then reload the page to look for the warning message that Turpentine will display at the top of the window. The cookie's name should be varnish_bypass and the value should be set to 1.
Start varnishhist from the command line. Start browsing the site (or wait for some traffic on the site if it's a live site). You will see '|' marks for each cache hit, and '#' for each cache miss.
Varnishlog can be both incredibly helpful and tricky to use. Start varnishlog from the command line and it'll just dump the log into standard output. Better is to direct it to a file and collect for awhile. Then you can use the tools of your choice to look through the file. Varnishlog is especially helpful for seeing when bans occur, and double-checking what items are being used to create the hash that Varnish stores objects by. For example, if Varnish is storing pages using different hash keys than your browser or warming script is requesting - there will be a lot of cache misses.
Watching server logs while testing can be useful to determine which requests are still being passed to the backend. For example, if a block is supposed to be cached privately, you should only see a request in the server logs the first time the user requests a page with that block. After that, the block should be cached privately for that user. You can identify the particular user by IP or by frontend cookie (which is past of the ESI URL request).
Because Varnish is adding another layer of caching to your Magento site, effectively clearing the cache is important whenever debugging - especially if you are testing a recent change. Usually, is sufficient to simply refresh all the cache types from the Cache Management screen in the Magento back-end. After that, open a fresh browser instance with no cookies for your site and begin testing.
When testing on a development site, first turn of all the other cache types under Cache Management in Magento. Then once you're satisfied with how the site is working, start turning them on one by one and testing for problems. It's not uncommon to have unexpected complications when other cache types are turned on.
Remember that the first page accessed by a new session is passed through by Varnish in order to get a valid session. This is the default behavior and can be changed in the back-end by change the 'Use VCL Fix' setting.
If debugging is turned on in the back-end, Turpentine will put quite a bit of useful information into the log. If you run into a problem be sure to check the logs - both the Magento log, the Turpentine log (if configured to log entries to a different log file) and the server log(s).
Most browsers have a "private" browsing mode (called "Incognito" in Chrome) which among other things does not save cookies when the window is closed. This is quite handy for testing, since you can just close the browser window to clear your browser cookies quickly. Alternatively, find/know a quick way to clear your site's frontend cookie quickly and easily.
When you encounter an error, first check to make sure that the issue does not occur when you turn on the varnish bypass cookie. This is the easiest way to ensure that the error is coming from Varnish or Turpentine, and is therefore (probably) not an underlying and unrelated issue.
It's not uncommon for sites to have issues with Ajax-powered features/plugins. Ajax uses javascript to send requests to back-end URLs to do something like adding a product to a shopping cart without needing to reload the page or navigate to a new URL.
Usually the problem is that the Ajax request has been cached by Varnish. The best solution is to simply find the URL of the Ajax request and construct a pattern to add to the URL blacklist under Caching Options in the Magento back-end. The easiest way to find out what Ajax requests are being sent is to use something like Chrome's developer tools to see network requests being made as you trigger the various Ajax functions.
Siege and other benchmarking tools are a useful way to evaluate your caching policies. The ideal tool will mimic real-world traffic (as much as possible).
The script below will run siege, using a list of store URLs (urls-bench1.txt generated from a sitemap) and simulating a load of 50 concurrent users. For more information about how to use siege, check out the official website.
for i in $(seq 1 5); do echo ${i}'.)'; siege –concurrent=50 –reps=100 -i -b -f urls-bench1.txt 2>&1 |grep -v HTTP/1.1|grep -v error |grep -vi siege |grep -v battle |grep -vi done |grep -v FILE |grep -v annoying|grep -v chunk |grep -v show-logfile; sleep 120; done
It is possible to add log statements to VCL (see this). For example, to add 'foo' to the varnishlog use this line in your VCL file:
std.log("foo");
Be sure the updated VCL gets applied to your running instance of Varnish then when using varnishlog you should see:
- VCL_Log foo