Search squid archive

Re: can't get squid to cache

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 

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@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@xxxxxxxxxxxxxxxxxxxxx:/usr/obj/usr/src/sys/GENERIC i386 

[root@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
[Index of Archives]     [Linux Audio Users]     [Samba]     [Big List of Linux Books]     [Linux USB]     [Yosemite News]

  Powered by Linux