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

Angelo Höngens wrote:
>
>>> 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
>
> Here's the output for the cache.log after one attempt.. (All following
> requests are exactly the same, all misses again where the store shows
> only 'RELEASE -1 FFFFFFFF' again):
>
>
>
> 2008/07/11 13:41:03| httpAccept: FD 11: accepted port 8001 client
> 127.0.0.1:65265
> 2008/07/11 13:41:04| clientReadRequest: FD 11: reading request...
> 2008/07/11 13:41:04| parseHttpRequest: Client HTTP version 1.0.
> 2008/07/11 13:41:04| parseHttpRequest: Method is 'GET'
> 2008/07/11 13:41:04| parseHttpRequest: URI is '/admin?op=ping'
> 2008/07/11 13:41:04| parseHttpRequest: req_hdr = {Accept: */*
>
> }
> 2008/07/11 13:41:04| parseHttpRequest: end = {}
> 2008/07/11 13:41:04| parseHttpRequest: prefix_sz = 44, req_line_sz = 29
> 2008/07/11 13:41:04| parseHttpRequest: Request Header is
> Accept: */*
>
>
> 2008/07/11 13:41:04| VPORT REWRITE: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| parseHttpRequest: Complete request received
> 2008/07/11 13:41:04| conn->in.offset = 0
> 2008/07/11 13:41:04| clientSetKeepaliveFlag: http_ver = 1.0
> 2008/07/11 13:41:04| clientSetKeepaliveFlag: method = GET
> 2008/07/11 13:41:04| The request GET http://127.0.0.1:8001/admin?op=ping
> is ALLOWED, because it matched 'all'
> 2008/07/11 13:41:04| clientRedirectStart:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| clientRedirectDone:
> 'http://127.0.0.1:8001/admin?op=ping' result=NULL
> 2008/07/11 13:41:04| clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET
> 2008/07/11 13:41:04| clientInterpretRequestHeaders: REQ_CACHABLE = SET
> 2008/07/11 13:41:04| clientInterpretRequestHeaders: REQ_HIERARCHICAL = SET
> 2008/07/11 13:41:04| clientProcessRequest: GET
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 13:41:04| clientProcessRequest2: storeGet() MISS
> 2008/07/11 13:41:04| clientProcessRequest: TCP_MISS for
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| clientProcessMiss: 'GET
> http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| storeCreateEntry:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| new_MemObject: returning 0x28336100
> 2008/07/11 13:41:04| new_StoreEntry: returning 0x2914f580
> 2008/07/11 13:41:04| storeKeyPrivate: GET
> http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 13:41:04| storeHashInsert: Inserting Entry 0x2914f580 key
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=2
> 2008/07/11 13:41:04| storeClientCopy: 36ADE22820C2FDE4586036DE72714B3A,
> seen 0, want 0, size 4096, cb 0x8065f20, cbdata 0x29155010
> 2008/07/11 13:41:04| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 13:41:04| storeClientCopy3: Waiting for more
> 2008/07/11 13:41:04| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 13:41:04| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=4
> 2008/07/11 13:41:04| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 13:41:04| storeLockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=4
> 2008/07/11 13:41:04| getMaxAge: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| storeAppend: appending 64 bytes for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| refreshCheck: 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| FRESH: age 3600 < min 216000
> 2008/07/11 13:41:04| Staleness = -1
> 2008/07/11 13:41:04| refreshCheck: Matched '. 216000 100% 216000'
> 2008/07/11 13:41:04| refreshCheck: age = 3600
> 2008/07/11 13:41:04| check_time: Fri, 11 Jul 2008 12:41:04 GMT
> 2008/07/11 13:41:04| entry->timestamp: Fri, 11 Jul 2008
> 11:41:04 GMT
> 2008/07/11 13:41:04| storeExpireNow: '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeReleaseRequest:
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeGet: looking up 9101138CFFBF419A08EFBB418D8264D7
> 2008/07/11 13:41:04| storeGet: looking up 5C590DE8852729BB7654D5EFFBB29519
> 2008/07/11 13:41:04| ctx: exit level 0
> 2008/07/11 13:41:04| storeAppend: appending 63 bytes for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 13:41:04| InvokeHandlers: checking client #0
> 2008/07/11 13:41:04| storeClientCopy2: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 13:41:04| storeClientCopy3: Copying from memory
> 2008/07/11 13:41:04| storeSwapOut: lowest_offset = 0
> 2008/07/11 13:41:04| clientSendMoreHeaderData:
> http://127.0.0.1:8001/admin?op=ping, 127 bytes
> 2008/07/11 13:41:04| clientSendMoreHeaderData: FD 11
> 'http://127.0.0.1:8001/admin?op=ping', out.offset=0
> 2008/07/11 13:41:04| clientSendMoreHeaderData: Appending 63 bytes after
> 64 bytes of headers
> 2008/07/11 13:41:04| The reply for GET
> http://127.0.0.1:8001/admin?op=ping is ALLOWED, because it matched 'all'
> 2008/07/11 13:41:04| storeSwapOut: http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 13:41:04| storeSwapOut: store_status = STORE_PENDING
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_lo = 0
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_hi = 127
> 2008/07/11 13:41:04| storeSwapOut: swapout.queue_offset = 0
> 2008/07/11 13:41:04| storeSwapOut: lowest_offset = 0
> 2008/07/11 13:41:04| storeComplete: '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeEntryValidLength: Checking
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeEntryValidLength: object_len = 127
> 2008/07/11 13:41:04| storeEntryValidLength: hdr_sz = 64
> 2008/07/11 13:41:04| storeEntryValidLength: content_length = 63
> 2008/07/11 13:41:04| storeSwapOut: http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 13:41:04| storeSwapOut: store_status = STORE_OK
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_lo = 0
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_hi = 127
> 2008/07/11 13:41:04| storeSwapOut: swapout.queue_offset = 0
> 2008/07/11 13:41:04| storeSwapOut: lowest_offset = 0
> 2008/07/11 13:41:04| InvokeHandlers: 36ADE22820C2FDE4586036DE72714B3A
> 2008/07/11 13:41:04| InvokeHandlers: checking client #0
> 2008/07/11 13:41:04| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=3
> 2008/07/11 13:41:04| storePendingNClients: returning 1
> 2008/07/11 13:41:04| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=2
> 2008/07/11 13:41:04| clientWriteComplete: FD 11, sz 258, err 0, off 127,
> len 127
> 2008/07/11 13:41:04| clientWriteComplete: FD 11 transfer is DONE
> 2008/07/11 13:41:04| connStateFree: FD 11
> 2008/07/11 13:41:04| httpRequestFree: http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 13:41:04| storeClientUnregister: called for
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| storeSwapOut: http://127.0.0.1:8001/admin?op=ping
> 2008/07/11 13:41:04| storeSwapOut: store_status = STORE_OK
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_lo = 0
> 2008/07/11 13:41:04| storeSwapOut: mem->inmem_hi = 127
> 2008/07/11 13:41:04| storeSwapOut: swapout.queue_offset = 0
> 2008/07/11 13:41:04| storeSwapOut: lowest_offset = 128
> 2008/07/11 13:41:04| storeSwapOut: lowest_offset = 128
> 2008/07/11 13:41:04| storePendingNClients: returning 0
> 2008/07/11 13:41:04| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=1
> 2008/07/11 13:41:04| storeUnlockObject: key
> '36ADE22820C2FDE4586036DE72714B3A' count=0
> 2008/07/11 13:41:04| storePendingNClients: returning 0
> 2008/07/11 13:41:04| storeRelease: Releasing:
> '36ADE22820C2FDE4586036DE72714B3A'
> 2008/07/11 13:41:04| destroy_StoreEntry: destroying 0x2914f580
> 2008/07/11 13:41:04| ctx: enter level 0:
> 'http://127.0.0.1:8001/admin?op=ping'
> 2008/07/11 13:41:04| destroy_MemObject: destroying 0x28336100
>
>
>
> By the way, I am running 2.6.STABLE16, since it's the latest in the
> FreeBSD ports. I like the ports, so I don't have to do manual
> installation or upgrade. But perhaps there are known bugs in this older
> version? Installed 'squid30' from ports as well, few days ago, it's
> 3.0.RC1, but that had the same problems.

Not much to choose from. Though more bugs have been found-n-fixed in 3.0
since RC1 than in 2.6 since STABLE16.

I think you got it right when you noticed the storeExpireNow. It's just
a matter of tracking down which of the several pathways to it thats
happening. I just hope somebody with more store experience can jump in
and help soon.

>
> [root_at_zvr-web-04 /var/log/squid]# uname -a
> FreeBSD zvr-web-04.zoovercolo.local 7.0-RELEASE FreeBSD 7.0-RELEASE #0:
> Sun Feb 24 19:59:52 UTC 2008
> root_at_logan.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC i386
>
> [root_at_zvr-web-04 /var/log/squid]# squid -v
> Squid Cache: Version 2.6.STABLE16
> configure options: '--bindir=/usr/local/sbin'
> '--sbindir=/usr/local/sbin' '--datadir=/usr/local/etc/squid'
> '--libexecdir=/usr/local/libexec/squid'
> '--localstatedir=/usr/local/squid' '--sysconfdir=/usr/local/etc/squid'
> '--enable-removal-policies=lru heap' '--disable-linux-netfilter'
> '--disable-linux-tproxy' '--disable-epoll' '--enable-auth=basic ntlm
> digest' '--enable-basic-auth-helpers=DB NCSA PAM MSNT SMB YP'
> '--enable-digest-auth-helpers=password'
> '--enable-external-acl-helpers=ip_user session unix_group wbinfo_group'
> '--enable-ntlm-auth-helpers=SMB'
> '--enable-negotiate-auth-helpers=squid_kerb_auth' '--enable-storeio=ufs
> diskd null' '--with-large-files' '--enable-large-cache-files'
> '--enable-err-languages=Armenian Azerbaijani Bulgarian Catalan Czech
> Danish Dutch English Estonian Finnish French German Greek Hebrew
> Hungarian Italian Japanese Korean Lithuanian Polish Portuguese Romanian
> Russian-1251 Russian-koi8-r Serbian Simplify_Chinese Slovak Spanish
> Swedish Traditional_Chinese Turkish'
> '--enable-default-err-language=English' '--prefix=/usr/local'
> '--mandir=/usr/local/man' '--infodir=/usr/local/info/'
> 'i386-portbld-freebsd7.0' 'build_alias=i386-portbld-freebsd7.0'
> 'host_alias=i386-portbld-freebsd7.0'
> 'target_alias=i386-portbld-freebsd7.0' 'CC=cc' 'CFLAGS=-O2
> -fno-strict-aliasing -pipe ' 'LDFLAGS=' 'CPPFLAGS='
>
>
> Angelo.
>

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