Caching responses with "Vary" header

When objects retrieved from web server return with a vary header, object is never cached and all future requests are always logged as a MISS.

Disabling the vary header on web server causes the same object to be cached as expected.

Seems to be same issues as discussed here : http://www.squid-cache.org/mail-archive/squid-dev/201207/0100.html

*** Bug 3799 has been marked as a duplicate of this bug. ***

Created attachment 2854
Set body size 0 on the vary marker object

I am suspecting that the recent changes to cache max-size is related to this. The internal Vary marker object we use in the cache has no body but was specifying 'unknown' body length instead of none.
 Please test this patch.

(In reply to comment #2)
> Created attachment 2854 [details]
> Set body size 0 on the vary marker object
>
> I am suspecting that the recent changes to cache max-size is related to this.
> The internal Vary marker object we use in the cache has no body but was
> specifying 'unknown' body length instead of none.
> Please test this patch.

Just tried the patch on Squid 3.2 in the context of bug 3799 and it did not make any difference. Does it require a higher version of Squid?

(In reply to comment #3)
> (In reply to comment #2)
> > Created attachment 2854 [details]
> > Set body size 0 on the vary marker object
> >
> > I am suspecting that the recent changes to cache max-size is related to this.
> > The internal Vary marker object we use in the cache has no body but was
> > specifying 'unknown' body length instead of none.
> > Please test this patch.
>
> Just tried the patch on Squid 3.2 in the context of bug 3799 and it did not
> make any difference. Does it require a higher version of Squid?

I also have tested with squid 3.3.3 and made no difference, what debugging can I turn on and logs to provide to help diagnose?

Thanks

Scott

Please find my analysis on this issue.
Squid 3.2.1
I have tracked this down to the way hash keys are generated and retrieved for requests with vary header. If you go to the squid source code file src/store_key_md5.cc (around line 100):

const cache_key *
storeKeyPublicByRequestMethod(HttpRequest * request, const HttpRequestMethod& method)
{
    static cache_key digest[SQUID_MD5_DIGEST_LENGTH];
    unsigned char m = (unsigned char) method.id();
    const char *url = urlCanonical(request);
    SquidMD5_CTX M;
    SquidMD5Init(&M);
    SquidMD5Update(&M, &m, sizeof(m));
    SquidMD5Update(&M, (unsigned char *) url, strlen(url));

    if (request->vary_headers)
SquidMD5Update(&M, (unsigned char *) request->vary_headers, strlen(request->vary_headers));
    SquidMD5Final(digest, &M);

    return digest;
}

you can see that MD5-based keys are generated based on request method id, request URL, and request vary header. The problem seems to be that when hash keys are generated during retrieval, the vary header field is empty and therefore although the resource is cached it cannot be retrieved because of the incorrect hash key.

If you comment out two lines from above as follows:

    //if (request->vary_headers)
//SquidMD5Update(&M, (unsigned char *) request->vary_headers, strlen(request->vary_headers));

and recompile squid you will see that such resources get served from cache indicating that the culprit is the vary header.

The part of the code that seems to be generating the hash keys for retrieval is inside src/store.cc (around line 625):

StoreEntry *
storeGetPublicByRequestMethod(HttpRequest * req, const HttpRequestMethod& method)
{
    return Store::Root().get(storeKeyPublicByRequestMethod(req, method));
}

Here the vary header of the http request object req is empty. Therefore storeKeyPublicByRequestMethod() returns the incorrect hash key for resource retrieval. Based on my investigation of the code the vary header during request gets stored in mem_obj->request->vary_headers based on response header (mem_obj is a member of StorEentry). For some reason during cache query the request member of mem_obj does not have valid vary_headers (it is empty).

An example test case is:

http://l1.yimg.com/zz/combo?os/mit/media/p/common/prime-dns-min-1137430.js&yui:3.8.1/build/yui/yui-min.js&ss/rapid-3.2.js&os/mit/media/m/base/imageloader-min-875847.js&os/mit/media/m/base/imageloader-bootstrap-min-815727.js&os/mit/media/m/base/viewport-loader-min-993847.js&os/mit/media/p/common/rmp-min-1127070.js

which has the vary header: “Vary:accept-encoding”. If you go this location in your browser, empty the browser cache, and then try to reload it you will see a cache miss in squid. If you comment out the two lines mentioned above and rebuild squid you will see that this becomes a cache hit.

I just want to report that this bug affects my client's e-commerce. I believe this is pretty serious: it's a common practice to compress js/css and "vary" header is mandatory in this case.
I'm unsure if wait for a fix or revert to 2.x version of squid.
Please, let me know if you plan to fix it asap.

(In reply to comment #5)

> you can see that MD5-based keys are generated based on request method id,
> request URL, and request vary header. The problem seems to be that when hash
> keys are generated during retrieval, the vary header field is empty and
> therefore although the resource is cached it cannot be retrieved because of the
> incorrect hash key.

I am not intimately familiar with this code, but I think empty vary_headers are expected on the first lookup. Looking at request alone, Squid does not yet know what request headers are subject to Vary control. To know that, Squid needs to retrieve the "master object" from the cache, find Vary header information there, fill vary_headers based on that information, do a second lookup, and retrieve the matching response from the cache (if any). Only during that second lookup the vary_headers member will be filled.

If your test case exposes the bug, then somebody needs to find out why the "master object" is not found in the cache during the first lookup (the one with empty vary_headers). To do that, one needs to investigate whether that "master object" was cached in the first place (when the original Vary response was received) and, if it was cached, why it was purged later (if it was purged) or why it was stored using a different key (also resulting in a miss).

(In reply to comment #7)
> (In reply to comment #5)
>
> > you can see that MD5-based keys are generated based on request method id,
> > request URL, and request vary header. The problem seems to be that when hash
> > keys are generated during retrieval, the vary header field is empty and
> > therefore although the resource is cached it cannot be retrieved because of the
> > incorrect hash key.
>
> I am not intimately familiar with this code, but I think empty vary_headers are
> expected on the first lookup. Looking at request alone, Squid does not yet know
> what request headers are subject to Vary control. To know that, Squid needs to
> retrieve the "master object" from the cache, find Vary header information
> there, fill vary_headers based on that information, do a second lookup, and
> retrieve the matching response from the cache (if any). Only during that second
> lookup the vary_headers member will be filled.
>
> If your test case exposes the bug, then somebody needs to find out why the
> "master object" is not found in the cache during the first lookup (the one with
> empty vary_headers). To do that, one needs to investigate whether that "master
> object" was cached in the first place (when the original Vary response was
> received) and, if it was cached, why it was purged later (if it was purged) or
> why it was stored using a different key (also resulting in a miss).

So we need couple cases:
1. request that has vary header in it(multi or single) and should have in the reply.
2. request that has a vary response in it without having one in the request.
3. request that has vary header in it(multi or single) and will not have vary header in the response.

The above cases will show how squid react in any situation that exists with vary headers on the request and response.
A vary header in the response should be equal to the request and if not still it should satisfy the request.
In the case which there is a vary header in the response but not in the request it should be ignored since HTTP should work by concept of "one request one response" and this is how a cache should cache the requests in http1.x.

if you do think of another cases put them here.

Eliezer

Created attachment 2969
proposed temporary fix for trunk

This patch contains several Vary caching fixes that make Vary caching work in my limited trunk tests.

One of the fixes is temporary -- it disables Vary response caching in shared memory cache (other caches should still work with these fixes). The same temporary change may also remove excessive "Vary object loop!" warnings in cache.log for folks using a shared memory cache.

The same patch may apply to earlier Squid versions. If you want to experiment, try patching with --fuzz=20 (if needed) and see whether the patch applies and the patched code compiles.

(In reply to comment #9)
> Created attachment 2969 [details]
> proposed temporary fix for trunk

The startWriting() piece seems to be the core bug here and this fixes it.
Applied to Squid-3 for further testing, absent any more progress this will be in 3.5.

Applied to 3.4 and 3.3