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

On 12/11/2013 03:06 AM, Martin Sperl wrote:
> Has anyone done any research into this already? Is there a fix?

Does http://bugs.squid-cache.org/show_bug.cgi?id=3806 help? I
incorrectly thought that fix was already in truck you were testing, but
it was not, until now (r13179; thanks, Amos!).

Alex.

> -----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 - 23:07:06 MST