Caching responses with "Vary" header

[Michael Nelson]

See the upstream bug report for more details [1], but it seems as though squid in trusty isn't caching any response which includes a vary header [2]. The upstream bug was fixed in 3.3.12 [3].

Steps to reproduce:
 * Setup an application returning responses with "Vary: User-Agent"
 * Add squid in front of an application server
 * Make multiple requests to squid

Expected result:
 * Second request is a Hit

Actual result:
 * Second (and subsequent) requests are all misses.

Repeat without a Vary header and things are cached as expected. Note, I've only reproduced this with a specific setup (as in [2]), I've not yet reproduced with a simplified setup to be certain I'm seeing the upstream bug.

[1] http://bugs.squid-cache.org/show_bug.cgi?id=3806
[2] http://paste.ubuntu.com/7736175/
[3] http://www.squid-cache.org/Versions/v3/3.3/changesets/SQUID_3_3_12.html

[Scott-harris (scott-harris)]

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

[Amos Jeffries (yadi)]

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

[Amos Jeffries (yadi)]

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.

[Sbaynes (sbaynes)]

(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?

[Scott-harris (scott-harris)]

(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

[Ahollyhock (ahollyhock)]

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.

[Andreatta-marco (andreatta-marco)]

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.

[Alex Rousskov (rousskov)]

(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).

[Eliezer Croitoru (eliezer)]

(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

[Alex Rousskov (rousskov)]

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.

[Amos Jeffries (yadi)]

(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.

[Amos Jeffries (yadi)]

Applied to 3.4 and 3.3

[Amos Jeffries (yadi)]

Debian Sid and Jesse package squid3 includes the fix for this bug. Please update the Ubuntu packages to match the upstream Debain repository.

[Robie Basak (racb)]

We're past feature freeze for Vivid now, so I can't just update to the latest any more, unless only bugfixes are involved or the release team grant an exception. If you can give me backported patches though, I can apply those. Otherwise a fix will need to wait until I can figure out backporting patches myself, or wait until Vivid is released.

[Michael Nelson (michael.nelson)]

On Fri, Feb 27, 2015 at 1:27 AM, Robie Basak <email address hidden> wrote:
> We're past feature freeze for Vivid now, so I can't just update to the
> latest any more, unless only bugfixes are involved or the release team
> grant an exception. If you can give me backported patches though, I can
> apply those.

I backported the fix to trusty as per the attached branch.

[Oleg Strikov (strikov)]

I prepared a debdiff for vivid (attached) and currently looking for sponsorship.
My repro case can be found here: http://pastebin.ubuntu.com/10527246/

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "lp-1336742-vivid.debdiff" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

[Oleg Strikov (strikov)]

Updated package has been pushed to vivid-proposed.
Feel free to try it.

[Launchpad Janitor (janitor)]

This bug was fixed in the package squid3 - 3.3.8-1ubuntu12

---------------
squid3 (3.3.8-1ubuntu12) vivid; urgency=medium

  * debian/tests/testlib_httpd.py: Use "service" command instead of upstart
    specific ones, and simplify the logic.
  * debian/tests/testlib.py, check_exe(): Check /proc/pid/exe symlink instead
    of parsing cmdline; the latter has "(squid-1)" with the init.d script, and
    it's not really what we are interested in.
 -- Martin Pitt <email address hidden> Fri, 06 Mar 2015 12:10:59 +0100

[Brian Murray (brian-murray)]

I'll go ahead and sponsor this.

[Chris J Arges (arges)]

Hello Michael, or anyone else affected,

Accepted squid3 into trusty-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/squid3/3.3.8-1ubuntu6.3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Michael Nelson (michael.nelson)]

On Wed, Jul 8, 2015 at 11:45 PM Chris J Arges <email address hidden>
wrote:

> Hello Michael, or anyone else affected,
>
>
Hi Chris,

Unfortunately I'm not able to reproduce the original problem with the
existing 3.3.8-1ubuntu6.2 (which is different to what I originally used) .
As I mentioned in the description, I'd not tested with a pristine trusty
environment, nor can I setup the same env with which I tested in the
original description.

In case I'm missing something obvious, and it helps someone else reproduce
the original issue and/or confirm the fix, here is how I tried to reproduce
the original problem just now on a freshly booted trusty instance:

http://paste.ubuntu.com/11853981/

Of course, if we're unable to reproduce the original issue, it may have
been specific to something in the environment I had (or have others seen
the same?). One possibility is that the app server I was using was sending
an incorrect Content-Length when Vary was present (as I noticed that an
incorrect Content-Length header causes squid to not cache, which is
understandable).

[Robie Basak (racb)]

Diogo will take a look for us to see if we can drive this through.

[Diogo Matsubara (matsubara)]

I verified the fix with Oleg's test case (comment #16). I first reproduced the issue in a pristine trusty environment with squid3 (3.3.8-1ubuntu6.2) and then installed the proposed package (3.3.8-1ubuntu6.3) and got a TCP_MEM_HIT/200 just like Oleg's example.

[Launchpad Janitor (janitor)]

This bug was fixed in the package squid3 - 3.3.8-1ubuntu6.3

---------------
squid3 (3.3.8-1ubuntu6.3) trusty-proposed; urgency=low

  * d/patches/fix-caching-vary-header.patch: Added upstream patch
    for the bug which prevented squid from caching responses with
    Vary header. (LP: #1336742) Based on work by Oleg Strikov.

 -- Rolf Leggewie <email address hidden> Wed, 01 Jul 2015 15:25:59 -0700

[Brian Murray (brian-murray)]

The verification of the Stable Release Update for squid3 has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.