ESI Processing Not Enabled appearing on certain pages

[zirwin]

I'm getting the "ESI Processing Not Enabled" error several other people have, and haven't been able to make it work yet using the solutions provided to others.

First off, my setup is Magento 1.6.1.0, Turpentine 0.5.2, Varnish 3.0.3, PHP 5.3.3-7+squeeze15, and APC 3.1.13. The block it's occuring in is the item compare block in a sidebar, as well as the footer, and I've noticed that it usually on the first, initial load of a particular page, but subsequent loads give the error. Here's the response headers from one of those pages, with debugging enabled:

HTTP/1.1 200 OK
Server: Apache/2.2.16 (Debian)
X-Powered-By: PHP/5.3.3-7+squeeze15
X-Turpentine-Cache: 1
X-Turpentine-Esi: 1
Content-Type: text/html; charset=UTF-8
X-Varnish-Set-Cookie: frontend=49375bdb-488b-488b-8c27-1ca77d66a07c; expires=Fri, 22-Mar-2013 03:10:25 GMT; path=/store; domain=seiboncarbon.com; httponly
Date: Fri, 22 Mar 2013 02:10:32 GMT
X-Varnish: 974223485 974223465
Age: 7
Via: 1.1 varnish
Connection: keep-alive
Set-Cookie: frontend=1858821d-be6f-4e6f-8193-703a47e633b2; expires=Fri, 22-Mar-2013 03:10:32 UTC; path=/store; domain=seiboncarbon.com; httponly
X-Varnish-Hits: 1

A request of that page directly to the backend, using the 'X-Turpentine-Secret-Handshake: 1' header, gives this:

HTTP/1.1 200 OK
Date: Fri, 22 Mar 2013 02:17:38 GMT
Server: Apache/2.2.16 (Debian)
X-Powered-By: PHP/5.3.3-7+squeeze15
Set-Cookie: frontend=hoe9rdp73llj29hfhe1phd0v63; expires=Fri, 22-Mar-2013 03:17:39 GMT; path=/store; domain=seiboncarbon.com; HttpOnly
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Pragma: no-cache
X-Turpentine-Cache: 1
X-Turpentine-Esi: 1
Vary: Accept-Encoding
Content-Type: text/html; charset=UTF-8

The body from this request contains the ESI block error (in this case I'm using the footer) with the url. Requesting that ESI url from the backend server directly, with the handshake header, gives the correct HTML body (the contents of the footer block) with these headers:

HTTP/1.1 200 OK
Date: Fri, 22 Mar 2013 02:24:37 GMT
Server: Apache/2.2.16 (Debian)
X-Powered-By: PHP/5.3.3-7+squeeze15
Set-Cookie: frontend=vvr4u2hj6c8la8iujril8gcj70; expires=Fri, 22-Mar-2013 03:24:38 GMT; path=/store; domain=seiboncarbon.com; HttpOnly
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Pragma: no-cache
X-Turpentine-Cache: 1
X-Turpentine-Esi: 0
Vary: Accept-Encoding
Content-Type: text/html; charset=UTF-8

Hopefully some part of this stands out as the source of the error, but I haven't been able to track it down so far. Any help would be appreciated.

[aheadley]

What webserver are you using? If it's Apache, can you list the modules you're using with httpd -M?

[zirwin]

Yes, it's apache. These modules are loaded:

Loaded Modules:
 core_module (static)
 log_config_module (static)
 logio_module (static)
 mpm_prefork_module (static)
 http_module (static)
 so_module (static)
 alias_module (shared)
 auth_basic_module (shared)
 authn_file_module (shared)
 authz_default_module (shared)
 authz_groupfile_module (shared)
 authz_host_module (shared)
 authz_user_module (shared)
 autoindex_module (shared)
 cgi_module (shared)
 deflate_module (shared)
 dir_module (shared)
 env_module (shared)
 mime_module (shared)
 negotiation_module (shared)
 php5_module (shared)
 reqtimeout_module (shared)
 rewrite_module (shared)
 setenvif_module (shared)
 ssl_module (shared)
 status_module (shared)

[aheadley]

Ok, can you start the Varnish logger with varnishlog > varnish.log, then flush the cache and reload one of the problematic pages until you see the "ESI processing not enabled" message? Once you see the error, refresh one more time (to flush out the log buffer), then compress the varnish.log file and email it to me (aheadley@nexcess.net).

[zirwin]

I've emailed the logs. Let me know if you'd rather have the raw log, or some other means of logging to get the information you're looking for.

[aheadley]

After looking through the logs Varnish doesn't seem to be even trying to do the ESI processing on that block. Can you try running varnishadm param.set esi_syntax 1, then flush the cache and see if that helps?

EDIT: Also, if varnishadm param.set esi_syntax 1 doesn't seem to make a difference, please try varnishadm param.set esi_syntax 7 (then flush the cache again).

[zirwin]

Doing each command and flushing the cache doesn't appear to have affected it either way; the error still turns up where it was showing up before in both cases.

[aheadley]

Can you check get the source of a page with the error (from Varnish, not the backend) with debugging enabled (looks like you already have this on), then compare the ESI URL in the debugging comment and the <esi:include> tag? For reference, you should see something like this:

        <!-- ESI START [footer] -->
<!-- ESI URL: <ESI URL here> -->
<esi:remove>ESI processing not enabled</esi:remove>
<!--esi <esi:include src="<ESI URL here>" /> -->
<!-- ESI END [footer] -->

Both URLs should be the same.

[zirwin]

This is fairly annoying; when debug mode is enabled, I do see the ESI debug comments, but the error never appears when it's active and the problem blocks load fine every time. When I disable debugging and clear the Varnish caches, the error comes right back.

[aheadley]

when debug mode is enabled, I do see the ESI debug comments, but the error never appears when it's active and the problem blocks load fine every time.

Well, that's useful info though. Can you try applying this patch then see if it still works with debugging disabled?

diff --git a/app/design/frontend/base/default/template/turpentine/esi.phtml b/app/design/frontend/base/default/template/turpentine/esi.phtml
index 2191a37..55250b1 100644
--- a/app/design/frontend/base/default/template/turpentine/esi.phtml
+++ b/app/design/frontend/base/default/template/turpentine/esi.phtml
@@ -24,10 +24,14 @@ $debugEnabled = (bool)Mage::helper( 'turpentine/esi' )->getEsiDebugEnabled();
 if( $debugEnabled ) {
     echo sprintf( '<!-- ESI START [%s] -->', $this->getNameInLayout() ) . PHP_EOL;
     echo sprintf( '<!-- ESI URL: %s -->', $this->getEsiUrl() ) . PHP_EOL;
+} else {
+    echo PHP_EOL;
 }
 echo sprintf( '<esi:remove>ESI processing not enabled</esi:remove>
 <!--esi <esi:include src="%s" /> -->',
     $this->getEsiUrl() ) . PHP_EOL;
 if( $debugEnabled ) {
     echo sprintf( '<!-- ESI END [%s] -->', $this->getNameInLayout() ) . PHP_EOL;
+} else {
+    echo PHP_EOL;
 }

[zirwin]

Applied patch, cleared cache, and the problem still persists with debugging disabled.

[aheadley]

Ok, a few more things to try then. First, can you see if having APC disabled makes a difference with and without that patch? If it doesn't, please try applying this patch (on top of the previous patch) with APC disabled still:

diff --git a/app/design/frontend/base/default/template/turpentine/esi.phtml b/app/design/frontend/base/default/template/turpentine/esi.phtml
index 55250b1..5fd5951 100644
--- a/app/design/frontend/base/default/template/turpentine/esi.phtml
+++ b/app/design/frontend/base/default/template/turpentine/esi.phtml
@@ -25,7 +25,8 @@ if( $debugEnabled ) {
     echo sprintf( '<!-- ESI START [%s] -->', $this->getNameInLayout() ) . PHP_EOL;
     echo sprintf( '<!-- ESI URL: %s -->', $this->getEsiUrl() ) . PHP_EOL;
 } else {
-    echo PHP_EOL;
+    echo '<!-- ESI START DUMMY COMMENT [] -->' . PHP_EOL;
+    echo '<!-- ESI URL DUMMY COMMENT -->' . PHP_EOL;
 }
 echo sprintf( '<esi:remove>ESI processing not enabled</esi:remove>
 <!--esi <esi:include src="%s" /> -->',
@@ -33,5 +34,5 @@ echo sprintf( '<esi:remove>ESI processing not enabled</esi:remove>
 if( $debugEnabled ) {
     echo sprintf( '<!-- ESI END [%s] -->', $this->getNameInLayout() ) . PHP_EOL;
 } else {
-    echo PHP_EOL;
+    echo '<!-- ESI END DUMMY COMMENT [] -->' . PHP_EOL;
 }

Thanks for helping with this, it's frustrating for me because I've not been able to reproduce it any of the times it's been reported and I'm sure doing all this debugging isn't fun for you either.

[zirwin]

Believe it or not, that seems to do the trick. I applied the changes, and the blocks show up properly. Just to be sure, I reverted to the previous version, cleared cache, and the errors were there; reapplied the changes, and the error was gone. Having the dummy text certainly seems to be the trigger. APC, by the way, was turned off at some point during debugging attempts; the previous results were with APC off.

As a side note, I'm not sure if it's related or not; as bots crawl the site, they pick up the ESI urls and (the ones that ignore robots.txt) tend to make requests against them. By looking through access logs, it seems like it variously gives the url /turpentine/esi/getBlock[etc] and /store/turpentine/esi/getBlock[etc]. The magento installation is in /store/, and it's set as the base URL in magento properly. There's also multiple stores in the install, for different regions. In chasing down leads, I came across this line in the template which, when compiled, yields:

if (req.url ~ "^(/store/netherlands/|/store/germany/|/store/taiwan/|/store/greece/|/store/japan/|/store/china/|/store/fb/|/store/uk/|/store/au/|/store/|/)(?:(?:index|litespeed)\.php/)?") {

which, curiously, has a lone '/' at the end, despite that not actually being the magento root. I mention it since it seems like it could both be related, and the sort of thing that would be easily overlooked in attempts at local reproduction.

[aheadley]

Believe it or not, that seems to do the trick.

Well, that's great news! I'll include that patch in the next release and talk to the Varnish guys to see if they know what's up with it.

which, curiously, has a lone '/' at the end, despite that not actually being the magento root.

The lone / root comes from your Magento configuration, you can see where the paths are found in the code. Maybe / is the base URL path for a different domain or something like that (note that that regex is not domain specific)? Or a store that is no longer used? Either way, I don't believe it's related to this issue, this seems to be a bug in Varnish's ESI parser.

[pieterjanliekens]

Hello just wanted to point out that the if{ } else { } loop does not nest the statement. This would result in always displaying the message.