RE: [squid-users] Wondering Why This Isn't Caching

From: Martin Sperl <Martin.Sperl_at_amdocs.com>
Date: Wed, 11 Dec 2013 10:06:31 +0000

Has anyone done any research into this already? Is there a fix?

Otherwise I would try to do a side by side comparison of 3.0 and trunk with full debugging enabled to see where the basic traces start to differ.
Then use that info as a hint into where the "regression" is rooted...

Martin

-----Original Message-----
From: Martin Sperl
Sent: Montag, 09. Dezember 2013 16:06
To: 'Amos Jeffries'; squid-users_at_squid-cache.org
Subject: RE: [squid-users] Wondering Why This Isn't Caching

Hi!

Has there been an fix to this yet?

This has also been discussed in this thread: "Squid icap respmod is not caching"

In the meantime I have been looking into it and have also come to the conclusion that it is related to "vary" in general and icap does not play any role in the issue - as soon as I add a Vary on the apache containing the content, the file becomes uncacheable independently from using icap or not.

Full debug shows with the latest trunk version of squid

Shows for a proxy request to http://www.sperl.org/test.css (which for testing purposes returns a "Vary:" header)

2013/12/09 05:52:31.751 kid1| client_side_request.cc(1513) processRequest: clientProcessRequest: GET 'http://www.sperl.org/test.css'
2013/12/09 05:52:31.751 kid1| client_side_request.cc(1536) httpStart: TAG_NONE for 'http://www.sperl.org/test.css'
2013/12/09 05:52:31.751 kid1| clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x135c5f0 from node 0x135c7c8
2013/12/09 05:52:31.751 kid1| cbdata.cc(510) cbdataReferenceValid: cbdataReferenceValid: 0x1359948
2013/12/09 05:52:31.751 kid1| HttpRequest.cc(696) storeId: sent back canonicalUrl:http://www.sperl.org/test.css
2013/12/09 05:52:31.751 kid1| store_dir.cc(935) get: storeGet: looking up 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:31.751 kid1| store_dir.cc(786) get: none of 1 cache_dirs have 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:31.751 kid1| client_side_reply.cc(1596) identifyFoundObject: clientProcessRequest2: StoreEntry is NULL - MISS
2013/12/09 05:52:31.751 kid1| client_side_reply.cc(613) processMiss: clientProcessMiss: 'GET http://www.sperl.org/test.css'
2013/12/09 05:52:31.751 kid1| store.cc(840) storeCreateEntry: storeCreateEntry: 'http://www.sperl.org/test.css'
2013/12/09 05:52:31.751 kid1| store.cc(422) StoreEntry: new StoreEntry 0x17986d0
2013/12/09 05:52:31.751 kid1| stmem.cc(397) mem_hdr: 0x14a8878 hi: 0
2013/12/09 05:52:31.751 kid1| MemObject.cc(88) MemObject: new MemObject 0x14a8850
2013/12/09 05:52:31.751 kid1| HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x1797b78 owner: 3
2013/12/09 05:52:31.752 kid1| cbdata.cc(324) cbdataInternalAlloc: cbdataAlloc: 0x1798188
2013/12/09 05:52:31.752 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 45
2013/12/09 05:52:31.752 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 9
2013/12/09 05:52:31.752 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 24
2013/12/09 05:52:31.752 kid1| store_key_md5.cc(109) storeKeyPrivate: storeKeyPrivate: GET http://www.sperl.org/test.css
2013/12/09 05:52:31.752 kid1| store.cc(502) hashInsert: StoreEntry::hashInsert: Inserting Entry 0x17986d0 key 'B2F8234EE3448A4D4BF1DC75049957AC'

Then after the proxy request:
2013/12/09 05:52:32.232 kid1| http.cc(919) haveParsedReplyHeaders: HTTP CODE: 200
2013/12/09 05:52:32.232 kid1| HttpRequest.cc(696) storeId: sent back canonicalUrl:http://www.sperl.org/test.css
2013/12/09 05:52:32.232 kid1| store_dir.cc(935) get: storeGet: looking up 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:32.232 kid1| store_dir.cc(786) get: none of 1 cache_dirs have 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:32.232 kid1| HttpRequest.cc(696) storeId: sent back canonicalUrl:http://www.sperl.org/test.css
2013/12/09 05:52:32.232 kid1| store_dir.cc(935) get: storeGet: looking up 444114273559944C370B6006D5DB69B8
2013/12/09 05:52:32.232 kid1| store_dir.cc(786) get: none of 1 cache_dirs have 444114273559944C370B6006D5DB69B8
2013/12/09 05:52:32.232 kid1| HttpHeader.cc(1127) has: 0x171fd78 lookup for 63
2013/12/09 05:52:32.232 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 63
2013/12/09 05:52:32.232 kid1| HttpHeader.cc(1002) getList: 0x171fd78: joined for id 63: accept-encoding
2013/12/09 05:52:32.232 kid1| HttpHeader.cc(1127) has: 0x1720168 lookup for 2
2013/12/09 05:52:32.232 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 73
2013/12/09 05:52:32.233 kid1| http.cc(656) httpMakeVaryMark: httpMakeVaryMark: accept-encoding
2013/12/09 05:52:32.233 kid1| refresh.cc(247) refreshCheck: refreshCheck: 'http://www.sperl.org/test.css'
2013/12/09 05:52:32.233 kid1| refresh.cc(262) refreshCheck: refreshCheck: Matched '. 0 20%% 259200'
2013/12/09 05:52:32.233 kid1| refresh.cc(264) refreshCheck: age: 60
2013/12/09 05:52:32.233 kid1| refresh.cc(266) refreshCheck: check_time: Mon, 09 Dec 2013 13:53:32 GMT
2013/12/09 05:52:32.233 kid1| refresh.cc(268) refreshCheck: entry->timestamp: Mon, 09 Dec 2013 13:52:32 GMT
2013/12/09 05:52:32.233 kid1| refresh.cc(204) refreshStaleness: STALE: age 60 > stale_age 25
2013/12/09 05:52:32.233 kid1| refresh.cc(288) refreshCheck: Staleness = 35
2013/12/09 05:52:32.233 kid1| http.cc(482) cacheableReply: YES because HTTP status 200
2013/12/09 05:52:32.233 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 63
2013/12/09 05:52:32.233 kid1| HttpHeader.cc(1002) getList: 0x171fd78: joined for id 63: accept-encoding
2013/12/09 05:52:32.233 kid1| HttpHeader.cc(1127) has: 0x1720168 lookup for 2
2013/12/09 05:52:32.233 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 73
2013/12/09 05:52:32.234 kid1| http.cc(656) httpMakeVaryMark: httpMakeVaryMark: accept-encoding
2013/12/09 05:52:32.234 kid1| store_dir.cc(935) get: storeGet: looking up 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:32.234 kid1| store_dir.cc(786) get: none of 1 cache_dirs have 64602E7E6AB4EAEAF19DD5097585466A
2013/12/09 05:52:32.234 kid1| store.cc(840) storeCreateEntry: storeCreateEntry: 'http://www.sperl.org/test.css'
2013/12/09 05:52:32.234 kid1| store.cc(422) StoreEntry: new StoreEntry 0x17b2b50
2013/12/09 05:52:32.234 kid1| stmem.cc(397) mem_hdr: 0x17a3318 hi: 0
2013/12/09 05:52:32.234 kid1| MemObject.cc(88) MemObject: new MemObject 0x17a32f0
2013/12/09 05:52:32.234 kid1| HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x1797b78 owner: 3
2013/12/09 05:52:32.234 kid1| cbdata.cc(324) cbdataInternalAlloc: cbdataAlloc: 0x1798188
2013/12/09 05:52:32.234 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 45
2013/12/09 05:52:32.234 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 9
2013/12/09 05:52:32.234 kid1| HttpHeader.cc(1127) has: 0x1797b78 lookup for 24
2013/12/09 05:52:32.234 kid1| store_key_md5.cc(109) storeKeyPrivate: storeKeyPrivate: GET http://www.sperl.org/test.css
2013/12/09 05:52:32.235 kid1| store.cc(502) hashInsert: StoreEntry::hashInsert: Inserting Entry 0x17b2b50 key '164CF6B5285D23A7E7789ED69BF05452'
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x17b2498 owner: 3
2013/12/09 05:52:32.235 kid1| cbdata.cc(324) cbdataInternalAlloc: cbdataAlloc: 0x1498848
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1127) has: 0x17b2498 lookup for 45
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1127) has: 0x17b2498 lookup for 9
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1127) has: 0x17b2498 lookup for 24
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x1791c40: 'Server : squid
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 52 at 0
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x179b980: 'Mime-Version : 1.0
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 38 at 1
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x179bb00: 'Date : Mon, 09 Dec 2013 13:52:32 GMT
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 21 at 2
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x17985c0: 'Content-Type : x-squid-internal/vary
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 18 at 3
2013/12/09 05:52:32.235 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x17a0560: 'Expires : Tue, 10 Dec 2013 17:39:12 GMT
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 24 at 4
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 63
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(1002) getList: 0x171fd78: joined for id 63: accept-encoding
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(1525) HttpHeaderEntry: created HttpHeaderEntry 0x17b1b10: 'Vary : accept-encoding
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(907) addEntry: 0x17b2498 adding entry: 63 at 5
2013/12/09 05:52:32.236 kid1| HttpHeader.cc(979) getList: 0x171fd78joining for id 73
2013/12/09 05:52:32.236 kid1| store.cc(1851) replaceHttpReply: StoreEntry::replaceHttpReply: http://www.sperl.org/test.css

And a little later:
2013/12/09 05:52:32.246 kid1| store.cc(1024) checkCachable: StoreEntry::checkCachable: NO: private key
2013/12/09 05:52:32.246 kid1| store.cc(556) setReleaseFlag: StoreEntry::setReleaseFlag: '164CF6B5285D23A7E7789ED69BF05452'
2013/12/09 05:52:32.246 kid1| store_swapout.cc(393) mayStartSwapOut: not cachable
2013/12/09 05:52:32.246 kid1| MemObject.cc(273) expectedReplySize: object_sz: -1
2013/12/09 05:52:32.246 kid1| MemObject.cc(279) expectedReplySize: clen: -1
2013/12/09 05:52:32.246 kid1| store_dir.cc(824) maybeTrimMemory: keepInLocalMemory: 1
2013/12/09 05:52:32.246 kid1| store_client.cc(761) invokeHandlers: InvokeHandlers: 164CF6B5285D23A7E7789ED69BF05452
2013/12/09 05:52:32.246 kid1| store.cc(1083) complete: storeComplete: '164CF6B5285D23A7E7789ED69BF05452'
2013/12/09 05:52:32.246 kid1| store.cc(1384) validLength: storeEntryValidLength: Checking '164CF6B5285D23A7E7789ED69BF05452'
2013/12/09 05:52:32.246 kid1| store.cc(1386) validLength: storeEntryValidLength: object_len = 210
2013/12/09 05:52:32.247 kid1| store.cc(1387) validLength: storeEntryValidLength: hdr_sz = 210
2013/12/09 05:52:32.247 kid1| store.cc(1388) validLength: storeEntryValidLength: content_length = -1
2013/12/09 05:52:32.247 kid1| store.cc(1391) validLength: storeEntryValidLength: Unspecified content length: 164CF6B5285D23A7E7789ED69BF05452
2013/12/09 05:52:32.247 kid1| store_swapout.cc(375) mayStartSwapOut: already rejected
2013/12/09 05:52:32.247 kid1| MemObject.cc(273) expectedReplySize: object_sz: 210
2013/12/09 05:52:32.247 kid1| store_dir.cc(824) maybeTrimMemory: keepInLocalMemory: 1
2013/12/09 05:52:32.247 kid1| store_client.cc(761) invokeHandlers: InvokeHandlers: 164CF6B5285D23A7E7789ED69BF05452
2013/12/09 05:52:32.247 kid1| store.cc(585) unlock: StoreEntry::unlock: key '164CF6B5285D23A7E7789ED69BF05452' count=0
2013/12/09 05:52:32.247 kid1| store_client.cc(786) storePendingNClients: storePendingNClients: returning 0
2013/12/09 05:52:32.247 kid1| store.cc(1276) release: storeRelease: Releasing: '164CF6B5285D23A7E7789ED69BF05452'
2013/12/09 05:52:32.247 kid1| store.cc(481) destroyStoreEntry: destroyStoreEntry: destroying 0x17b2b58
2013/12/09 05:52:32.247 kid1| store.cc(459) destroyMemObject: destroyMemObject 0x17a32f0
2013/12/09 05:52:32.247 kid1| MemObject.cc(111) ~MemObject: del MemObject 0x17a32f0
2013/12/09 05:52:32.247 kid1| ctx: enter level 1: 'http://www.sperl.org/test.css'
2013/12/09 05:52:32.247 kid1| stmem.cc(87) freeContent: 0x17a3318 hi: 0
2013/12/09 05:52:32.247 kid1| HttpHeader.cc(442) clean: cleaning hdr: 0x17b2498 owner: 3
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x1791c40: 'Server: squid'
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x179b980: 'Mime-Version: 1.0'
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x179bb00: 'Date: Mon, 09 Dec 2013 13:52:32 GMT'
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x17985c0: 'Content-Type: x-squid-internal/vary'
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x17a0560: 'Expires: Tue, 10 Dec 2013 17:39:12 GMT'
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(1531) ~HttpHeaderEntry: destroying entry 0x17b1b10: 'Vary: accept-encoding'
2013/12/09 05:52:32.248 kid1| cbdata.cc(348) cbdataInternalFree: cbdataFree: 0x1498848
2013/12/09 05:52:32.248 kid1| cbdata.cc(365) cbdataInternalFree: cbdataFree: Freeing 0x1498848
2013/12/09 05:52:32.248 kid1| HttpHeader.cc(442) clean: cleaning hdr: 0x17b2498 owner: 3
2013/12/09 05:52:32.248 kid1| ctx: exit level 1
2013/12/09 05:52:32.248 kid1| stmem.cc(87) freeContent: 0x17a3318 hi: 0

And finally:
2013/12/09 05:52:32.251 kid1| HttpRequest.cc(696) storeId: sent back canonicalUrl:http://www.sperl.org/test.css
2013/12/09 05:52:32.251 kid1| store_key_md5.cc(150) storeKeyPublicByRequestMethod: updating public key by vary headers: accept-encoding for: http://www.sperl.org/test.css
2013/12/09 05:52:32.251 kid1| store.cc(502) hashInsert: StoreEntry::hashInsert: Inserting Entry 0x17986d0 key '4D4B35818AB6D7147A9DFD1142793BD4'
2013/12/09 05:52:32.251 kid1| HttpHeader.cc(1127) has: 0x171fd78 lookup for 41
2013/12/09 05:52:32.251 kid1| ctx: exit level 0

So we got several different IDs for the same request:
64602E7E6AB4EAEAF19DD5097585466A to start (only contains the URL)
B2F8234EE3448A4D4BF1DC75049957AC the proxy request private ID

We then have temporarily the proxied request ID: 64602E7E6AB4EAEAF19DD5097585466A
Which immediately gets translated back: 444114273559944C370B6006D5DB69B8

We also create an id: 164CF6B5285D23A7E7789ED69BF05452

And we create a new object with: Content-Type : x-squid-internal/vary
Surprisingly this does not get stored anywhere, so it gets deleted.

Finally the object gets delivered and inserted into the store as '4D4B35818AB6D7147A9DFD1142793BD4'

And via "squidclient mgr:objects" one finds:
KEY 4D4B35818AB6D7147A9DFD1142793BD4
        STORE_OK IN_MEMORY SWAPOUT_DONE PING_DONE
        CACHABLE,DISPATCHED,VALIDATED
        LV:1386597152 LU:1386597152 LM:1386597023 EX:-1
        0 locks, 0 clients, 1 refs
        Swap Dir 0, File 0X000003
        GET http://www.sperl.org/test.css
        vary_headers: accept-encoding
        inmem_lo: 0
        inmem_hi: 328
        swapout: 328 bytes queued

Also the x-squid-internal/vary HTTPReply object for x-squid-internal/vary does not show up in cache.

So we essentially miss the "correct" lookup for key "4D4B35818AB6D7147A9DFD1142793BD4" to get the "correct" object from cache - not 64602E7E6AB4EAEAF19DD5097585466A.

As far as I can tell we would need is:
* store the "x-squid-internal/vary" object in StoreEntry::setPublicKey
* when looking for the "original" object in the store and it is not found, then search for the x-squid-internal/vary object to see if we find it and if so take the Vary header to look up the real object. (unfortunately I have not found out where that would need to happen)

Maybe someone has an idea if the above is possible and where the logic would need to get added...

Thanks,
        Martin

P.s: if there is NO Vary header, then:
2013/12/09 05:52:31.751 kid1| HttpRequest.cc(696) storeId: sent back canonicalUrl:http://www.sperl.org/test.css
2013/12/09 05:52:31.751 kid1| store_dir.cc(935) get: storeGet: looking up 64602E7E6AB4EAEAF19DD5097585466A
Finds the object immediately and delivers from cache...

-----Original Message-----
From: Amos Jeffries [mailto:squid3_at_treenet.co.nz]
Sent: Donnerstag, 05. September 2013 09:07
To: squid-users_at_squid-cache.org
Subject: Re: [squid-users] Wondering Why This Isn't Caching

On 5/09/2013 5:35 a.m., Geoffrey Schwartz wrote:
> I have a page which gets cached by Firefox. Google Page Speed says it's
> cacheable as well. Squid does not cache it.
>
> I'm running Squid v3.3.8. My configuration is pretty standard... I'll post
> it if need be.
>
> The page is being served through Apache's mod_asis so I can explicitly set
> the headers. Here it is:
>
> =====
> Status: 200 A-OK
> Date: Wed, 04 Sep 2013 15:32:28 GMT
> Cache-Control: public
> Expires: Thu, 05 Sep 2013 15:32:28 GMT
> Vary: Accept-Encoding
> Content-Type: text/html
>
> <html>
> <body>
> hello, world
> </body>
> </html>
> =====
>
> When I visit the page in Firefox (I have to disable browser caching in
> order to get it to send the request in the first place), my browser
> sends/receives the following headers (according to Firebug):
> =====
> GET http://example.com/test.asis HTTP/1.1
> Host: example.com
> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:23.0)
> Gecko/20100101 Firefox/23.0
> Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
> Accept-Language: en-US,en;q=0.5
> Accept-Encoding: gzip, deflate
> Connection: keep-alive
>
> HTTP/1.1 200 OK
> Date: Wed, 04 Sep 2013 17:09:48 GMT
> Server: Apache/2.2.25 (Unix) mod_ssl/2.2.25 OpenSSL/1.0.1e DAV/2
> mod_perl/2.0.7 Perl/v5.12.4
> Cache-Control: public
> Expires: Thu, 05 Sep 2013 15:32:28 GMT
> Vary: Accept-Encoding
> Content-Length: 43
> Content-Type: text/html
> X-Cache: MISS from webcache-dev1.cc.columbia.edu
> Via: 1.1 webcache-dev1.cc.columbia.edu (squid/3.3.8)
> Connection: keep-alive
> =====
>
> I get this response every time (as in, X-Cache: MISS). I know the Date
> header gets changed (probably by apache using the last-modified time) as
> well as the Status, but the Expires header is still there (and still in the
> future). This should be cached, right? Apparently Google's Page Speed
> tool and Firefox think so.
>
> Out of curiosity, I removed the Vary header. Squid then started caching
> the page.
>
> Did I run into a bug with 3.3.8? I did several searches but wasn't able to
> find anything about this issue.

You did. There is something very strange happening with the special
cache Vary-marker object used to identify different variants of the
object behind the URL. for some reason those are not being cached for
very long by by 3.2 and later which prevents the variants being HIT on
sometimes.

Amos

This message and the information contained herein is proprietary and confidential and subject to the Amdocs policy statement,
you may review at http://www.amdocs.com/email_disclaimer.asp
Received on Wed Dec 11 2013 - 10:06:46 MST

This archive was generated by hypermail 2.2.0 : Thu Dec 12 2013 - 12:00:04 MST