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@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
