This is using Varnish 4 and ESI.

I'm not sure if this is an error, or there needs to be some improvement in the VCL file or how blocks are processed. In testing the Mini Panels patch I wrote (https://www.drupal.org/project/authcache/issues/2231701), I also ran a simple experiment where a Mini Panel is added as a block using Authcache Block.

This seemed to work without problem, since it's essentially just loading a block to the page. However, I did see one peculiar result in watchdog. Every time a block would be initially loaded, it threw the following error:

User: test_user
Location: http://testsite.io/authcache-varnish-get-key
Message: Excluded: Authcache varnish key callback

I added a watchdog message at the top of authcache_p13n_frontcontroller_handle_request, and it returned what I expected for $req:

$req = Array
(
    [a] => 
    [r] => frag/block/panels_mini-header_above
)

Also the important $_SERVER values at the start of authcache_p13n_frontcontroller_handle_request seemed to be correct:

    [SCRIPT_FILENAME] => /app/authcache.php
    [QUERY_STRING] => a=&r=frag/block/panels_mini-header_above&o%5Bq%5D=front
    [REQUEST_METHOD] => GET
    [SCRIPT_NAME] => /authcache.php
    [REQUEST_URI] => /authcache.php?a=&r=frag/block/panels_mini-header_above&o%5Bq%5D=front
    [DOCUMENT_URI] => /authcache.php
    [HTTP_COOKIE] => SESSb25cb6e5f7953f35d59a6b9a07ea7b5c=t4zEI8kBrBe4Onatu-e45DdR6MnBgaw3hnLbZ9LzSBk; aucp13n=9bcpn6
    [HTTP_X_AUTHCACHE_DO_ESI] => 1
    [HTTP_X_AUTHCACHE] => 1
    [HTTP_X_AUTHCACHE_KEY] => 3996d18
    [HTTP_X_AUTHCACHE_GET_KEY] => done
    [HTTP_X_VARNISH] => 819745
    [HTTP_X_AUTHCACHE_VARNISH_PASSPHRASE] => correct horse battery staple
    [PHP_SELF] => /authcache.php

What's also strange is the second block loaded the warning in watchdog with a user of "Anonymous":

User: Anonymous (not verified)
Location: http://testsite.io/authcache-varnish-get-key
Message: Excluded: Authcache varnish key callback

But the $req and $_SERVER watchdog statements after this "Exclude" returned the correct test_user user.

Any thoughts on what could be causing this, or where to investigate? The page is still being cached and receive a HIT from Varnish, but the message doesn't make sense.

Comments

ron_s created an issue. See original summary.

sgdev’s picture

Issue summary: View changes
znerol’s picture

Category: Bug report » Support request
User: test_user
Location: http://testsite.io/authcache-varnish-get-key
Message: Excluded: Authcache varnish key callback

This is not so obvious but it actually is expected behavior. authcache-varnish-get-key is the callback invoked from the VCL to retrieve the authcache key for the currently logged in user (or the current anonymous session). See the comments in core.vcl for more info. This callback is excluded from the page cache (in the drupal part) but the response will still be cached in varnish because of the headers added to the response.

sgdev’s picture

Thanks for clarifying. I had read that comment in core.vcl and understood the "authcache-varnish-get-key" processing, but did not realize it would log as an "exclude" to watchdog.

So essentially it is being included as a status message of where it is in the process? I'm wondering if there is a way to make this a bit more descriptive to help a developer understand what is happening.