Ok - I have just tried the latest version from trunk and it seems to do what it is expected to do now! So the question is: will this patch also go into 3.4Beta or do we have to wait for 3.5 to get this resolved? Thanks, Martin -----Original Message----- From: Alex Rousskov [mailto:rousskov@xxxxxxxxxxxxxxxxxxxxxxx] Sent: Donnerstag, 12. Dezember 2013 00:07 To: squid-users@xxxxxxxxxxxxxxx Cc: Martin Sperl Subject: Re: 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@xxxxxxxxxxxxxxx > Subject: RE: 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@xxxxxxxxxxxxx] > Sent: Donnerstag, 05. September 2013 09:07 > To: squid-users@xxxxxxxxxxxxxxx > Subject: Re: 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 >
