ESI Cache Policy seems not work with private blocks

[gianstraf]

Hi, in my Magento 1.9 CE installation (Nexcessnet_Turpentine v. 0.7.1), I've a serious problem about caching of this blocks:

<reference name="header">
            <action method="setEsiOptions">
                <params>
                    <access>private</access>
                    <flush_events>
                        <wishlist_item_save_after/>
                        <wishlist_item_delete_after/>
                        <sales_quote_save_after/>
                        <controller_action_layout_render_before_catalogsearch_result_index />
                        <persistent_session_expired/>
                    </flush_events>
                </params>
            </action>
        </reference>

I expect that one version per client is stored in cache. I see that Varnish does not cache that block, but return for it an hit_for_pass. New request is done to backend server, each time that same user refresh page.

I tried to debugging with this request (frontend cookie is valid):

curl -I --cookie "frontend=s0mn492vgh4os624ep75n1n074" http://mytestdomain.com/store/store_code/turpentine/esi/getBlock/method/esi/access/private/ttl/60/hmac/f0a7d52f8ca10aaef8476d53c0298665ec1d6607914a3c77071cd84d965aa3c5/data/0mSxZKTFIU_V2ITw5Ml1YyW2AbkMxTQJd74inCX375xGInyS44LDWotRFyn3bEy96Bpdremm8_b_rvu3Yl1dP9GLtGIoHtnxV3V8lQGYaO7LTbgo2UrX9x6xjecGg5VJCyOhCWHC9Ryg97xhss42G4HhE_chUVs5rY1U84_BCFgwr6ZVUqRD9GJ_vI7jSSHUKxFY4sjrQbECbwlz6D4Ixp9SdpQUZg32Zx5oKNG3pcub96pMaambe91NpbNtRN3zJEcLAqYfJdoKvIsAY31Mwoe7RNh9YPkz_pRBKjUeYrW1o53CFRwe-esGCPFT2HwaJvIofcb69yf-xnTmq-uAcPWElgzbORjuMIFZhsAhYd3Iopxv3PwdJZInWE__BA3xIgcAdykb4Gbruqt1doSrF5bQ393PWl5sWjoVDFgpv12f_HCUR7VdpgBxDkJQdU6XkpJVLtTxCFaNXkqoqs5PlQxYUA2Xi245ksYh6Er5XnV0ocHfQ1hGsgf9lq2NZ2JHt-F36Jm1TfMZNnbq4SNWWWHK3czVurx7/

It seems that beresp.http.X-Turpentine-Cache is always 0. This the vcl fragment:

sub vcl_fetch {
   #...
           if (beresp.http.X-Turpentine-Esi == "1") {
                set beresp.do_esi = true;
            }
            if (beresp.http.X-Turpentine-Cache == "0") {
                set beresp.ttl = 15s;
                return (hit_for_pass);
            } else {
                #...
            }
    #...
   return (deliver);
}

I see this code in controllers/EsiController.php (around row 104):

$block->setEsiOptions(false);

and in Model/Observer/Esi.php (around row 233):

  if ($esiHelper->shouldResponseUseEsi() &&
                $blockObject instanceof Mage_Core_Block_Template &&
                $esiOptions = $blockObject->getEsiOptions()) {
    //....
      // change the block's template to the stripped down ESI template
            switch ($esiOptions[$methodParam]) {
                case 'ajax':
                    $blockObject->setTemplate('turpentine/ajax.phtml');
                    break;

                case 'esi':
                default:
                    $blockObject->setTemplate('turpentine/esi.phtml');
                    // flag request for ESI processing
                    Mage::register('turpentine_esi_flag', true, true);
            }
   }

Debugging I see that: $blockObject->getEsiOptions() is always empty, and code:

default:
         $blockObject->setTemplate('turpentine/esi.phtml');
         // flag request for ESI processing
       Mage::register('turpentine_esi_flag', true, true);

won't be never reached. As a result for this, function setFlagHeaders in Model/Observer/Esi.php will return always this response header :

X-Turpentine-Esi = 0

and esi block request won't be ever cached. This causes a big number of unuseful requests to backend server, overloading it. Are you aware of this problem?

Thanks

[gianstraf]

Hi guys, any idea about this issue ? Nobody met the same problems ?

Thanks, Gianluca

[miguelbalparda]

I'm pretty sure your problem is somewhere else, probably in the architecture of the theme you are using. What have you tried so far to debug this?

[gianstraf]

Hi Miguel, I've enabled this flags in System > Configuration > Varnish Options:

• Enable Debug Info
• Enable Block Logging

After, I opened source of a site page to catch ESI url for header esi block (or others esi block with scope private):

http://mytestdomain.com/store/store_code/turpentine/esi/getBlock/method/esi/access/private/ttl/60/hmac/f0a7d52f8ca10aaef8476d53c0298665ec1d6607914a3c77071cd84d965aa3c5/data/0mSxZKTFIU_V2ITw5Ml1YyW2AbkMxTQJd74inCX375xGInyS44LDWotRFyn3bEy96Bpdremm8_b_rvu3Yl1dP9GLtGIoHtnxV3V8lQGYaO7LTbgo2UrX9x6xjecGg5VJCyOhCWHC9Ryg97xhss42G4HhE_chUVs5rY1U84_BCFgwr6ZVUqRD9GJ_vI7jSSHUKxFY4sjrQbECbwlz6D4Ixp9SdpQUZg32Zx5oKNG3pcub96pMaambe91NpbNtRN3zJEcLAqYfJdoKvIsAY31Mwoe7RNh9YPkz_pRBKjUeYrW1o53CFRwe-esGCPFT2HwaJvIofcb69yf-xnTmq-uAcPWElgzbORjuMIFZhsAhYd3Iopxv3PwdJZInWE__BA3xIgcAdykb4Gbruqt1doSrF5bQ393PWl5sWjoVDFgpv12f_HCUR7VdpgBxDkJQdU6XkpJVLtTxCFaNXkqoqs5PlQxYUA2Xi245ksYh6Er5XnV0ocHfQ1hGsgf9lq2NZ2JHt-F36Jm1TfMZNnbq4SNWWWHK3czVurx7/

I got the value of the magento frontend cookie, and used it to simulate varnish esi request with curl (by command line).

Starting by this request, I followed Nexcessnet_Turpentine module starting by EsiController, to view because response header X-Turpentine-Esi was always 0 (I've analyzed code, inserting Mage::log in module).

With that header varnish does not cache request beacouse it meets this vcl code:

sub vcl_fetch {
   #...
           if (beresp.http.X-Turpentine-Esi == "1") {
                set beresp.do_esi = true;
            }
            if (beresp.http.X-Turpentine-Cache == "0") {
                set beresp.ttl = 15s;
                return (hit_for_pass);
            } else {
                #...
            }
    #...
   return (deliver);
}

Thank you, Gianluca

[miguelbalparda]

Can you try using the ESI decoder to see what does that request means? When I say this might be because of your theme structure, it is because of the structure of your theme, when you try to cache a block that is actually inside or nested in another block with a different cache policy, things might go south.

[gianstraf]

Here output of esi-decoder.php:

array (
  'block_type' => 'Mage_Page_Block_Html_Header',
  'complex_registry' => 
  array (
  ),
  'design_package' => 'GeneralTheme',
  'design_theme' => 'default',
  'dummy_blocks' => 
  array (
  ),
  'esi_method' => 'esi',
  'flush_events' => 
  array (
    0 => 'customer_login',
    1 => 'customer_logout',
    2 => 'wishlist_item_save_after',
    3 => 'wishlist_item_delete_after',
    4 => 'sales_quote_save_after',
    5 => 'controller_action_layout_render_before_catalogsearch_result_index',
    6 => 'persistent_session_expired',
  ),
  'layout_handles' => 
  array (
    0 => 'default',
    1 => 'THEME_frontend_GeneralTheme_default',
    4 => 'customer_logged_out',
    13 => 'cms_index_index',
  ),
  'name_in_layout' => 'header',
  'simple_registry' => 
  array (
  ),
  'store_id' => '7',
)

[gianstraf]

Proceding with the analisy, I've verified that the block isn't inside or nested in another block with a different cache policy. I find the same problems with others ESI private blocks. Here the esi-decode result for the block "recently viewed products" :

array (
  'block_type' => 'Nexcessnet_Turpentine_Block_Product_Viewed',
  'complex_registry' => 
  array (
  ),
  'design_package' => 'GeneralTheme',
  'design_theme' => 'default',
  'dummy_blocks' => 
  array (
  ),
  'esi_method' => 'esi',
  'flush_events' => 
  array (
    0 => 'customer_login',
    1 => 'customer_logout',
    2 => 'catalog_controller_product_view',
  ),
  'layout_handles' => 
  array (
    0 => 'default',
    1 => 'THEME_frontend_GeneralTheme_default',
  ),
  'name_in_layout' => 'right.reports.product.viewed',
  'simple_registry' => 
  array (
  ),
  'store_id' => '7',
)

It seems so strange that I am the only one to detect this behavior :(

Tanks, Gianluca

[gianstraf]

Hi Miguel, what do you think about this code in controllers/EsiController.php ?

 if ($block) {
                    $blockEsiOptions = $block->getEsiOptions();

// ###################################################
                    //IS THIS LINE REALLY NEEDED ?
                    $block->setEsiOptions(false);
// ###################################################

                    $resp->setBody($block->toHtml());
                    if ((int) $req->getParam($esiHelper->getEsiTtlParam()) > 0) {
                        $cacheFlag = true;
                        if (isset($blockEsiOptions['only_cache_if'])) {
                            switch ($blockEsiOptions['only_cache_if']) {
                                case 'empty':
                                    $cacheFlag = ('' === $resp->getBody());
                                    break;
                                case 'no_text':
                                    $cacheFlag = ('' === trim(strip_tags($resp->getBody())));
                                    break;
                                default:
                                    $cacheFlag = false;
                            }
                        }
                    }

This seems the cause of problem. I don't understand becouse it is needed. Can you help me ?

Thank you

[gianstraf]

Hi, the problem was this configuration:

If lifetime is 0 or not configured, the module does not do a properly fallback on php environment session max_lifetime: _session.gcmaxlifetime

The function getDefaultEsiTtl in Turpentine/Helper/Data.php is:

 public function getDefaultEsiTtl() {
        return trim(Mage::getStoreConfig('web/cookie/cookie_lifetime'));
  }

Instead, core function getLifeTime in resource model Mage/Core/Model/Resource/Session.php, works with a default:

if ($this->_lifeTime < 60) {
          $this->_lifeTime = ini_get('session.gc_maxlifetime');
}

I think function could be fixed to work as the core function. Do you agree ?

Thanks, Gianluca

[miguelbalparda]

@gianstraf that makes sense, feel free to ope a pull request with this fix.

[miguelbalparda]

@gianstraf email me and I'll help you with that.

[gianstraf]

I sent you an e-mail with the patch details.

[miguelbalparda]

I didn't get any emails, can you create the pull request from your fork and point it to the devel branch?

[gianstraf]

Done. Thanks, Gianluca