[Plugin: W3 Total Cache] Intermittent Browser Decode Errors

Below is the access log from another two tests today. Here is the transcript of my first session.

a) Opened browser, checked google calendar, opened up our site with W3TC enabled in a new tab and received an Error 330. [9:42:26]

b) Closed all browser windows completely, opened up browser, navigated to our site with W3TC enable, and it appears instantly, fine. [9:44:01]

Looking at the access logs (no other traffic in this window, I have included all logs from this time frame, nothing in error log), in the second working case, the web site was still loaded completely from cache as there were no additional requests – which is great, but why the decode error on the first attempt?

70.28.78.161 – – [10/Apr/2012:09:42:26 -0400] “GET / HTTP/1.1” 200 3487 “-” “Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.151 Safari/535.19”
70.28.78.161 – – [10/Apr/2012:09:42:42 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:42:42 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:42:42 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:42:42 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:42:42 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:44:01 -0400] “GET / HTTP/1.1” 200 3474 “-” “Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.151 Safari/535.19”
70.28.78.161 – – [10/Apr/2012:09:44:15 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:44:15 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:44:15 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:44:15 -0400] “-” 400 0 “-” “-“
70.28.78.161 – – [10/Apr/2012:09:44:15 -0400] “-” 400 0 “-” “-“

Here is the second session from another computer, using IE8 this time. In this case I hit the main page [09:55:30] no issues and it is served from cache except the minified css and js, proceed to the /products URL [09:55:35] and receive the equivalent decode error from IE. I close the browser, re-open and go directly to the /products URL [09:56:43 and the page loads correctly. In this case, I can see the “page prime” occur on the server [09:56:44] , but I am not sure this has an impact on my request or [suspected] browser caching issues.

70.28.78.161 – – [10/Apr/2012:09:55:30 -0400] “GET / HTTP/1.1” 200 3474 “-” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
70.28.78.161 – – [10/Apr/2012:09:55:30 -0400] “GET /wp-content/w3tc/min/85bc4f72.88aa3a.css HTTP/1.1” 200 10388 “https://www.netstatz.com/” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
70.28.78.161 – – [10/Apr/2012:09:55:30 -0400] “GET /wp-content/w3tc/min/3fe8f48e.5b2675.js HTTP/1.1” 200 47708 “https://www.netstatz.com/” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
70.28.78.161 – – [10/Apr/2012:09:55:35 -0400] “GET /products/ HTTP/1.1” 200 4924 “https://www.netstatz.com/” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
70.28.78.161 – – [10/Apr/2012:09:56:43 -0400] “GET /products/ HTTP/1.1” 200 4904 “-” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /sitemapindex.xml HTTP/1.0” 200 1036 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /site.xml HTTP/1.0” 200 700 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /post.xml HTTP/1.0” 200 896 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /page.xml HTTP/1.0” 200 1236 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /taxonomy_category.xml HTTP/1.0” 200 1078 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:43 -0400] “GET /?w3tc_preload=1 HTTP/1.0” 200 15181 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /microsoft-enables-linux/?w3tc_preload=1 HTTP/1.0” 200 22419 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /site-update/?w3tc_preload=1 HTTP/1.0” 200 21888 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /wordpress-performance/?w3tc_preload=1 HTTP/1.0” 200 19997 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /monitoring-tool/?w3tc_preload=1 HTTP/1.0” 200 18878 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /services/?w3tc_preload=1 HTTP/1.0” 200 18563 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /products/?w3tc_preload=1 HTTP/1.0” 200 19972 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /category/netstatz/?w3tc_preload=1 HTTP/1.0” 200 18263 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /category/industry/vps/?w3tc_preload=1 HTTP/1.0” 200 16137 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “GET /category/industry/?w3tc_preload=1 HTTP/1.0” 200 15956 “-” “W3 Total Cache/0.9.2.5b”
96.8.120.21 – – [10/Apr/2012:09:56:44 -0400] “POST /wp-cron.php?doing_wp_cron=1334066203 HTTP/1.0” 200 1 “-” “WordPress/3.3.1; https://www.netstatz.com”
70.28.78.161 – – [10/Apr/2012:09:56:46 -0400] “GET /wp-content/w3tc/min/9a9148a4.c95cfe.js HTTP/1.1” 200 38734 “https://www.netstatz.com/products/” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”
70.28.78.161 – – [10/Apr/2012:09:56:47 -0400] “GET /wp-content/w3tc/min/9a9148a4.c95cfe.js HTTP/1.1” 200 47965 “https://www.netstatz.com/products/” “Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)”

I am going to mess around with disabling the client caching encouragement techniques (various headers set in W3TC browser config)

-unset expires header
-unset cache control header
-review cache-control policy (currently set-with-max-age)
-unset entity tag (eTag)

It seems the browser messes things up on its own, without getting fresh data from the server other than the first 200. I suspect there is something about the headers on that first 200 that prevent proper referral/alignment to the cached data.

I also believe I see this problem on browsers that have never been to the site – which is counter intuitive to the caching configuration issue.

I have modified my W3TC browser cache config to disable gzip compression. I have confirmed that nginx does not have gzip set, and w3tc nginx.conf is not setting it and that nginx gzip default is still off (all expected).

However I still have a gzip encoding header. It looks like I have introduced a config issue with phpfpm (my assumption right now). I thought I had ruled out double encoding already, but missed something. I’ll confirm my assumptions later, but it doesn’t appear W3TC has anything to do with my issue after further investigation.

After a thorough review of my setup, it seemed that the gzip encoding was not my phpfpm or nginx; So even though I had disabled the W3TC browser cache gzip settings (in the general part, and each sub-section of the config), I went ahead and disabled the entire W3TC plugin.

And at that point the gzip encoding stopped.

After re-enabling W3TC and turning on the same browser cache settings without the gzip enabled, I am now seeing the expected text/html encoding on my web site pages.

It seems that there is something strange going on with the gzip configuration W3TC is applying.

Verification of nginx conf rewrites and nginx restarts following settings changes does not seem to be a factor. I use the auto-install which seem to be accurately detect when settings have been properly applied – both in terms of auto-install to nginx.conf and if the server is using them (reload/restart).

After more testing I can confirm that the decode error I am seeing is only present when HTML/XML gzip option is enabled; So I have disabled it for now.

I also confirmed what looks like a related bug. If you follow these steps, gzip encoding is still enabled even though it should not be.

a) Turn on Browser Cache with gzip enabled generally and restart nginx/phpfpm.
b) Confirm in browser content encoding as expected
c) Turn off the HTML/XML gzip compression
d) Restart nginx/phpfpm to reload config
e) Clear browser cache and close browser
f) Open up and go to website
g) Additionally refresh the page
h) Headers still show content encoding gzip
i) Confirm w3tc config shows false in written configuration

It seems the configuration is being ignored for whatever reason when you follow these steps. Deactivation and re-activation is one workaround.

In nginx, turning gzip on automatically gzips text/html. It cannot be turned of unless you turn gzip off altogether. So enabling gzip for css, media files etc enables it for html as well.

About original issue. What cache engines were you using when it occurred? disk, apc, memcache. Also what caches did you enable? Page Cache object etc?