Re: [squid-users] can't get squid to cache

Angelo Hongens wrote:
> Amos Jeffries wrote:
>> Angelo Hongens wrote:
>>> Sorry, sent this mail directly to Hendrik.. Here it is to the list. I'm
>>> still pulling my hear out :(
>>>
>>>
>>> Henrik Nordstrom wrote:
>>>>> On ons, 2008-07-09 at 14:32 +0200, Angelo Höngens wrote:
>>>>>
>>>>>>> Is there any way I can force caching if the control headers are
>>>>>>> missing??
>>>>> refresh_pattern with a min age does this.
>>> I expect this line in my squid.conf should take care of that?
>>>
>>> refresh_pattern . 3600 100% 3600 ignore-no-cache ignore-reload
>>> override-expire override-lastmod
>>>
>>>
>>>
>>>>>>> Here's two records from access.log:
>>>>>>>
>>>>>>> 1215606505.637 1678 10.94.206.73 TCP_MISS/200 3262 GET
>>>>>>> http://10.94.206.77:8001/bin?id=ACC83639Zoover-NL&irversion=510
>>>>>>> - FIRST_UP_PARENT/10.94.206.34 text/html 1215606506.990 1352
>>>>>>> 10.94.206.73 TCP_MISS/200 3262 GET
>>>>>>> http://10.94.206.77:8001/bin?id=ACC83639Zoover-NL&irversion=510
>>>>>>> - FIRST_UP_PARENT/10.94.206.34 text/html
>>>>> Make sure you are not denying caching of query URLs (cache
>>>>> directive), and that there is a refresh_pattern with a min age.
>>> I expect these lines in my squid.conf to take care of that:
>>>
>>> acl all src 0.0.0.0/0.0.0.0
>>> cache allow all
>>>
>>>>> The best way to test is to use squidclient, both to Squid and the web
>>>>> server. This will show you exactly what is going on with no mangling
>>>>> of the HTTP headers what so ever.
>>> Exactly the same..
>>>
>>> source server:
>>> -------------------------------------------------
>>> [angelo_at_zvr-web-04 ~]$ squidclient -h 10.94.206.34 -p 8001
>>> "/admin?op=ping"
>>> HTTP/1.0 200 OK
>>> Content-Type: text/html
>>> Content-Length: 63
>>>
>>> dgraph zvr-end-04:8001 responding at Wed Jul 09 16:13:18 2008
>>> -------------------------------------------------
>>>
>>> local squid:
>>> -------------------------------------------------
>>> [angelo_at_zvr-web-04 ~]$ squidclient -h localhost -p 8001
>>> "/admin?op=ping"
>>> HTTP/1.0 200 OK
>>> Content-Type: text/html
>>> Content-Length: 63
>>> X-Cache: MISS from zvr-web-04.zoovercolo.local
>>> Via: 1.0 zvr-web-04.zoovercolo.local:8001 (squid/2.6.STABLE16)
>>> Connection: close
>>>
>>> dgraph zvr-end-04:8001 responding at Wed Jul 09 16:13:53 2008
>>> -------------------------------------------------
>>>
>>>
>>> Any more ideas? Thanks in advance :)
>>
>> The first request through cache is usually expected to MISS, its the
>> second which tells you whether or not the caching was success/failure.
>>
>> Try:
>> squidclient -h 10.94.206.34 -p 8001 "/admin?op=ping"
>> squidclient -h localhost -p 8001 "/admin?op=ping"
>> squidclient -h localhost -p 8001 "/admin?op=ping"
>>
>> and see what the third response is.
>>
>> If it still fails, configure "debug_options 22,9 20,5", purge the
>> cache.log and try the above three again. Hopefully the cache.log will be
>> left with a trace of what happend to non-cache the reply.
>>
>> Amos
>> --
>> Please use Squid 2.7.STABLE3 or 3.0.STABLE7
>
> I added the line "debug_options 22,9 20,5" somewhere in my config, and
> restarted squid.
>
> The ran the three squidclient commands.
>
> access.log shows the same:
>
> 1215758508.849 2 127.0.0.1 TCP_MISS/200 258 GET
> http://127.0.0.1:8001/admin?op=ping - FIRST_UP_PARENT/zvr-end-04 text/html
> 1215758508.855 2 127.0.0.1 TCP_MISS/200 258 GET
> http://127.0.0.1:8001/admin?op=ping - FIRST_UP_PARENT/zvr-end-04 text/html
>
> store.log as well:
>
> 1215758508.849 RELEASE -1 FFFFFFFF 36ADE22820C2FDE4586036DE72714B3A 200
> -1 -1 -1 text/html 63/63 GET
> http://127.0.0.1:8001/admin?op=ping
> 1215758508.855 RELEASE -1 FFFFFFFF B8B52D283D5FC8A54EA6E12A1D1EAED4 200
> -1 -1 -1 text/html 63/63 GET
> http://127.0.0.1:8001/admin?op=ping
>
> But now the cache.log has some more info, which I do not fully understand:
>
> Any ideas?:
>
> 2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 08:41:48| storeCreateEntry:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| new_MemObject: returning 0x28336100
> 2008/07/11 08:41:48| new_StoreEntry: returning 0x2914f580
> 2008/07/11 08:41:48| storeKeyPrivate: GET
> http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 08:41:48| storeHashInsert: Inserting Entry 0x2914f580 key
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=2
> 2008/07/11 08:41:48| storeClientCopy: 36ADE22820C2FDE4586036DE72714B3A,
> seen 0, want 0, size 4096, cb 0x8065f20, cbdata 0x29155010
> 2008/07/11 08:41:48| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 08:41:48| storeClientCopy3: Waiting for more
> 2008/07/11 08:41:48| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 08:41:48| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=4
> 2008/07/11 08:41:48| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 08:41:48| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=4
> 2008/07/11 08:41:48| getMaxAge: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| storeAppend: appending 64 bytes for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| refreshCheck: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| FRESH: age 3600 < min 216000
> 2008/07/11 08:41:48| Staleness = -1
> 2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
> 2008/07/11 08:41:48| refreshCheck: age = 3600
> 2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
> 2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
> 2008/07/11 08:41:48| storeExpireNow: '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storeReleaseRequest:
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 08:41:48| storeGet: looking up 5C590DE8852729BB7654D5EFFBB29519
> 2008/07/11 08:41:48| ctx: exit level 0
> 2008/07/11 08:41:48| storeAppend: appending 63 bytes for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 08:41:48| InvokeHandlers: checking client #0
> 2008/07/11 08:41:48| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 08:41:48| storeClientCopy3: Copying from memory
> 2008/07/11 08:41:48| storeComplete: '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storeEntryValidLength: Checking
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storeEntryValidLength: object_len = 127
> 2008/07/11 08:41:48| storeEntryValidLength: hdr_sz = 64
> 2008/07/11 08:41:48| storeEntryValidLength: content_length = 63
> 2008/07/11 08:41:48| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 08:41:48| InvokeHandlers: checking client #0
> 2008/07/11 08:41:48| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 08:41:48| storePendingNClients: returning 1
> 2008/07/11 08:41:48| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=2
> 2008/07/11 08:41:48| storeClientUnregister: called for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| storePendingNClients: returning 0
> 2008/07/11 08:41:48| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=1
> 2008/07/11 08:41:48| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=0
> 2008/07/11 08:41:48| storePendingNClients: returning 0
> 2008/07/11 08:41:48| storeRelease: Releasing:
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 08:41:48| destroy_StoreEntry: destroying 0x2914f580
> 2008/07/11 08:41:48| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| destroy_MemObject: destroying 0x28336100
> 2008/07/11 08:41:48| ctx: exit level 0
> 2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 08:41:48| storeCreateEntry:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| new_MemObject: returning 0x28336100
> 2008/07/11 08:41:48| new_StoreEntry: returning 0x2914f580
> 2008/07/11 08:41:48| storeKeyPrivate: GET
> http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 08:41:48| storeHashInsert: Inserting Entry 0x2914f580 key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storeLockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=2
> 2008/07/11 08:41:48| storeClientCopy: B8B52D283D5FC8A54EA6E12A1D1EAED4,
> seen 0, want 0, size 4096, cb 0x8065f20, cbdata 0x29155010
> 2008/07/11 08:41:48| storeClientCopy2: B8B52D283D5FC8A54EA6E12A1D1EAED4
> 2008/07/11 08:41:48| storeClientCopy3: Waiting for more
> 2008/07/11 08:41:48| storeLockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
> 2008/07/11 08:41:48| storeLockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=4
> 2008/07/11 08:41:48| storeUnlockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
> 2008/07/11 08:41:48| storeLockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=4
> 2008/07/11 08:41:48| getMaxAge: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| storeAppend: appending 64 bytes for
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| refreshCheck: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| FRESH: age 3600 < min 216000
> 2008/07/11 08:41:48| Staleness = -1
> 2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
> 2008/07/11 08:41:48| refreshCheck: age = 3600
> 2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
> 2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
> 2008/07/11 08:41:48| storeExpireNow: 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storeReleaseRequest:
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 08:41:48| storeGet: looking up 5C590DE8852729BB7654D5EFFBB29519
> 2008/07/11 08:41:48| ctx: exit level 0
> 2008/07/11 08:41:48| storeAppend: appending 63 bytes for
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| InvokeHandlers: B8B52D283D5FC8A54EA6E12A1D1EAED4
> 2008/07/11 08:41:48| InvokeHandlers: checking client #0
> 2008/07/11 08:41:48| storeClientCopy2: B8B52D283D5FC8A54EA6E12A1D1EAED4
> 2008/07/11 08:41:48| storeClientCopy3: Copying from memory
> 2008/07/11 08:41:48| storeComplete: 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storeEntryValidLength: Checking
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storeEntryValidLength: object_len = 127
> 2008/07/11 08:41:48| storeEntryValidLength: hdr_sz = 64
> 2008/07/11 08:41:48| storeEntryValidLength: content_length = 63
> 2008/07/11 08:41:48| InvokeHandlers: B8B52D283D5FC8A54EA6E12A1D1EAED4
> 2008/07/11 08:41:48| InvokeHandlers: checking client #0
> 2008/07/11 08:41:48| storeUnlockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=3
> 2008/07/11 08:41:48| storePendingNClients: returning 1
> 2008/07/11 08:41:48| storeUnlockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=2
> 2008/07/11 08:41:48| storeClientUnregister: called for
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| storePendingNClients: returning 0
> 2008/07/11 08:41:48| storeUnlockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=1
> 2008/07/11 08:41:48| storeUnlockObject: key
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4' count=0
> 2008/07/11 08:41:48| storePendingNClients: returning 0
> 2008/07/11 08:41:48| storeRelease: Releasing:
> 'B8B52D283D5FC8A54EA6E12A1D1EAED4'
> 2008/07/11 08:41:48| destroy_StoreEntry: destroying 0x2914f580
> 2008/07/11 08:41:48| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 08:41:48| destroy_MemObject: destroying 0x28336100
>
>
> Looks like the object is expiring, because I see the storeExpireNow
> command. But I don't get exactly why it's expiring.. Well, I see
> something in the log, but I do not understand what it means:
>
> 2008/07/11 08:41:48| FRESH: age 3600 < min 216000
> 2008/07/11 08:41:48| Staleness = -1
> 2008/07/11 08:41:48| refreshCheck: Matched '. 216000 100% 216000'
> 2008/07/11 08:41:48| refreshCheck: age = 3600
> 2008/07/11 08:41:48| check_time: Fri, 11 Jul 2008 07:41:48 GMT
> 2008/07/11 08:41:48| entry->timestamp: Fri, 11 Jul 2008 06:41:48 GMT
> 2008/07/11 08:41:48| storeExpireNow: '36ADE22820C2FDE4586036DE72714B3A'
>

Ah, okay its not a standard release, that would have shown up in the
trace just prior to the storeExpireNow.
Maybe the level I told you is not quite enough. Is there aything else
showign up with "debug_options 22,9 20,8 33,8"?

Amos

-- 
Please use Squid 2.7.STABLE3 or 3.0.STABLE7