Re: [squid-users] Seemingly incorrect behavior: squid cache getting filled up on PUT requests

I think I found the problem. This applies only to HTTPs traffic being
cached with ssl-bump.
Basically HttpRequest::maybeCacheable() does not check for PROTO_HTTPS

Following patch fixes it:

<patch>
diff --git a/squid-3.HEAD-20140127-r13248/src/HttpRequest.cc
b/squid-3.HEAD-20140127-r13248/src/HttpRequest.cc
index dc18b33..ce6c411 100644
--- a/squid-3.HEAD-20140127-r13248/src/HttpRequest.cc
+++ b/squid-3.HEAD-20140127-r13248/src/HttpRequest.cc
@@ -596,6 +596,7 @@ HttpRequest::maybeCacheable()
     switch (protocol) {
     case AnyP::PROTO_HTTP:
+ case AnyP::PROTO_HTTPS:
         if (!method.respMaybeCacheable())
             return false;

</patch>

-Rajiv

On Mon, Feb 17, 2014 at 12:54 AM, Rajiv Desai <rajiv_at_maginatics.com> wrote:
> FWIW, from debug logs in cache.log, it seems like PUT responses are
> being cached.
> I am fairly new to using squid so I am be completely misreading these.
> Just trying to understand caching.
> So are PUT responses cached by design? or am I completely missing
> something simple here? :)
>
>
> <logs>
> 2014/02/17 00:06:54.977 kid1| store_dir.cc(1149) get: storeGet:
> looking up AC671962CFC5644F4B22DA51C242DA50
> 2014/02/17 00:06:54.977 kid1| StoreMap.cc(293) openForReading: opening
> entry with key AC671962CFC5644F4B22DA51C242DA50 for reading
> /mnt/squid-cache_inodes
> 2014/02/17 00:06:54.977 kid1| StoreMap.cc(309) openForReadingAt:
> opening entry 14877 for reading /mnt/squid-cache_inodes
> 2014/02/17 00:06:54.977 kid1| StoreMap.cc(322) openForReadingAt:
> cannot open empty entry 14877 for reading /mnt/squid-cache_inodes
> 2014/02/17 00:06:54.977 kid1| store_dir.cc(820) find: none of 1
> cache_dirs have AC671962CFC5644F4B22DA51C242DA50
> 2014/02/17 00:06:54.977 kid1| client_side_reply.cc(1626)
> identifyFoundObject: StoreEntry is NULL - MISS
> 2014/02/17 00:06:54.977 kid1| client_side_reply.cc(622) processMiss:
> clientProcessMiss: 'PUT
> https://s3-us-west-1.amazonaws.com/mag-1363987602-cmbogo/334677ce-9882104'
> 2014/02/17 00:06:54.977 kid1| store.cc(803) storeCreatePureEntry:
> storeCreateEntry:
> 'https://s3-us-west-1.amazonaws.com/mag-1363987602-cmbogo/334677ce-9882104'
> 2014/02/17 00:06:54.977 kid1| store.cc(395) StoreEntry: StoreEntry
> constructed, this=0x168f990
> </logs>
>
> ... and later
>
> <logs>
> 2014/02/17 00:06:55.127 kid1| store_dir.cc(820) find: none of 1
> cache_dirs have DBA199D500F44928560537BB0CAB0908
> 2014/02/17 00:06:55.127 kid1| refresh.cc(319) refreshCheck: checking
> freshness of 'https://s3-us-west-1.amazonaws.com/mag-1363987602-cmbogo/334677ce-9882104'
> 2014/02/17 00:06:55.127 kid1| refresh.cc(340) refreshCheck: Matched '.
> 7776000 100%% 7776000'
> 2014/02/17 00:06:55.127 kid1| refresh.cc(342) refreshCheck: age: 60
> 2014/02/17 00:06:55.127 kid1| refresh.cc(344) refreshCheck:
> check_time: Mon, 17 Feb 2014 08:07:55 GMT
> 2014/02/17 00:06:55.127 kid1| refresh.cc(346) refreshCheck:
> entry->timestamp: Mon, 17 Feb 2014 08:06:55 GMT
> 2014/02/17 00:06:55.127 kid1| refresh.cc(202) refreshStaleness: No
> explicit expiry given, using heuristics to determine freshness
> 2014/02/17 00:06:55.128 kid1| refresh.cc(240) refreshStaleness: FRESH:
> age (60 sec) is less than configured minimum (7776000 sec)
> 2014/02/17 00:06:55.128 kid1| refresh.cc(366) refreshCheck: Staleness = -1
> 2014/02/17 00:06:55.128 kid1| refresh.cc(486) refreshCheck: Object isn't stale..
> 2014/02/17 00:06:55.128 kid1| refresh.cc(501) refreshCheck: returning
> FRESH_MIN_RULE
> 2014/02/17 00:06:55.128 kid1| http.cc(491) cacheableReply: YES because
> HTTP status 200
> 2014/02/17 00:06:55.128 kid1| HttpRequest.cc(696) storeId: sent back
> canonicalUrl:https://s3-us-west-1.amazonaws.com/mag-1363987602-cmbogo/334677ce-9882104
> 2014/02/17 00:06:55.128 kid1| store.cc(472) hashInsert:
> StoreEntry::hashInsert: Inserting Entry e:=p2DV/0x168f990*3 key
> 'AC671962CFC5644F4B22DA51C242DA50'
> 2014/02/17 00:06:55.128 kid1| ctx: exit level 0
> 2014/02/17 00:06:55.128 kid1| store.cc(858) write: storeWrite: writing
> 17 bytes for 'AC671962CFC5644F4B22DA51C242DA50'
> </logs>
>
> On Sun, Feb 16, 2014 at 11:07 PM, Rajiv Desai <rajiv_at_maginatics.com> wrote:
>> What is the authoritative source of cache statistics? The slots
>> occupied due to PUT requests (as suggested by mgr:storedir stats is
>> quite concerning.
>> Is there some additional config that needs to be added to ensure that
>> PUTs are simply bypassed for caching purpose.
>>
>> NOTE: fwiw, I have verified that subsequent GETs for the same objects
>> after PUTs do get a cache MISS.
>>
>> On Sun, Feb 16, 2014 at 3:45 PM, Rajiv Desai <rajiv_at_maginatics.com> wrote:
>>> On Sun, Feb 16, 2014 at 3:39 PM, Amos Jeffries <squid3_at_treenet.co.nz> wrote:
>>>> On 17/02/2014 11:41 a.m., Rajiv Desai wrote:
>>>>> I am using Squid Cache:
>>>>> Version 3.HEAD-20140127-r13248
>>>>>
>>>>> My cache dir is configured to use rock (Large rock with SMP):
>>>>> cache_dir rock /mnt/squid-cache 256000 max-size=4194304
>>>>>
>>>>> My refresh pattern is permissive to cache all objects:
>>>>> refresh_pattern . 129600 100% 129600 ignore-auth
>>>>>
>>>>> I uploaded 30 GB of data via squid cache with PUT requests.
>>>>> From storedir stats(squidclient mgr:storedir) it seems like each PUT
>>>>> is occupying 1 slot in rock cache.
>>>>>
>>>>> Is this a known bug? PUT requests should not increase cache usage right?
>>>>>
>>>>>
>>>>> Stats:
>>>>>
>>>>> by kid9 {
>>>>>
>>>>> Store Directory Statistics:
>>>>>
>>>>> Store Entries : 53
>>>>>
>>>>
>>>>
>>>> How may objects in that 30GB of PUT requests?
>>>>
>>>> That 53 looks more like the icons loaded by Squid for use in error pages
>>>> and ftp:// directory listings.
>>>>
>>>
>>> 572557 objects were uploaded with PUT requests.
>>> I was looking at current size and used slots to interpret current
>>> cache occupancy. Perhaps I am interpreting these incorrectly?
>>>
>>> Current Size: 8960416.00 KB 4.27%
>>> Current entries: 560025 4.27%
>>> Used slots: 560025 4.27%
>>>
>>>> Amos
>>>>
Received on Tue Feb 18 2014 - 00:23:46 MST