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

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'

-- 
Met vriendelijke groet,
Angelo Höngens