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

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

[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.
Received on Fri Jul 11 2008 - 11:54:15 MDT