Re: acl help

Roger,

Do you have icp_hit_stale set to "on"? Looks like something disables refresh
checks for ICP hits...

Alex.

On Fri, 11 Sep 1998, Roger Yerramsetti wrote:

> On Thu, 10 Sep 1998, Alex Rousskov wrote:
>
> | On Thu, 10 Sep 1998, Roger Yerramsetti (Wantree) wrote:
>
> | > Here is an output from calamaris that show's the siblings hitting our
> | > squid1.2beta23p4 server
> | >
> | > # TCP-Requests Request % kByte % Hit-%
> | > ----------------------------------------- ------- ------ -------- ------------
> | > proxy2.omen.com.au 29434 2.76 239840 2.76 78.64
> | > bridge.q-net.net.au 17223 1.61 126434 1.45 72.86
> | >
> | > proxy2.omen is squid 1.1, bridge.q-net is 1.2b24
> | >
> | > Any thoughts on what to do or paths to follow in tracking down the
> | > problem?
>
> | Try analyzing replies that have "X-Cache-Lookup: HIT" but "X-Cache: MISS"
> | with full debugging enabled. That may tell you what part of the
> | refresh/validation algorithm fails. Also, I think there is a cache manager
> | option that reports the histogram for "reasons for refresh failures". Check
> | that out.
>
> Thanks for the tip on where to start :)
>
> This is something I noticed when looking at cache.log with squid -k debug
>
> I've attached the full log exerpt regarding this, but here is the cutdown
> :) Please keep in mind, I do not know too much how squid works.
>
> 1998/09/11 01:53:31| commSetSelect: FD 71 type 1
> 1998/09/11 01:53:31| icpHandleUdp: FD 71: received 87 bytes from 203.24.101.16.
> 1998/09/11 01:53:31| init-ing hdr: 0x114d66b0 owner: 1
> 1998/09/11 01:53:31| aclCheckFast: list: 0x81502b8
> 1998/09/11 01:53:31| aclMatchAclList: checking all
> 1998/09/11 01:53:31| aclMatchAcl: checking 'acl all src 0.0.0.0/0.0.0.0'
> 1998/09/11 01:53:31| aclMatchIp: h = 0.0.0.0
> 1998/09/11 01:53:31| aclMatchIp: addr1 = 0.0.0.0
> 1998/09/11 01:53:31| aclMatchIp: addr2 = 0.0.0.0
> 1998/09/11 01:53:31| aclMatchIp: returning 1
> 1998/09/11 01:53:31| aclMatchAclList: returning 1
> 1998/09/11 01:53:31| storeGet: looking up 4C88D268A66A52E0044352F2C277EB27
> 1998/09/11 01:53:31| icpHandleIcpV2: OPCODE ICP_QUERY
> 1998/09/11 01:53:31| icpUdpSend: FD 71 sending ICP_HIT, 83 bytes to 203.24.101.16:3130
> 1998/09/11 01:53:31| cleaning hdr: 0x114d66b0 owner: 1
>
> Ok, an ICP request has come in for
> 'http://www.excite.com/entertainment/r_and_x_rated/free_images/' which
> appears to be 4C88D268A66A52E0044352F2C277EB27 from 203.24.101.16.
> (bridge.q-net.net.au)
>
> My proxy server (proxy1.per.wantree.comm.au) sends back an ICP_HIT.
>
> bridge.q-net tries to fetch it now. squid goes through checking of acl's
> re dangerous ports etc etc
>
> It passes all that, and states the following (cacheable, tcp_hit etc),
> then goes to open the appropriate file.
>
> 1998/09/11 01:53:31| clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET
> 1998/09/11 01:53:31| clientInterpretRequestHeaders: REQ_CACHABLE = SET
> 1998/09/11 01:53:31| clientInterpretRequestHeaders: REQ_HIERARCHICAL = SET
> 1998/09/11 01:53:31| clientProcessRequest: GET 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| storeGet: looking up 4C88D268A66A52E0044352F2C277EB27
> 1998/09/11 01:53:31| clientProcessRequest: TCP_HIT for 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| storeLockObject: key '4C88D268A66A52E0044352F2C277EB27' count=1
> 1998/09/11 01:53:31| creating rep: 0x8ecee40
> 1998/09/11 01:53:31| init-ing hdr: 0x8ecee78 owner: 2
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 33
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 9
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 20
> 1998/09/11 01:53:31| new_MemObject: returning 0x9296220
> 1998/09/11 01:53:31| cbdataAdd: 0x14736b60
> 1998/09/11 01:53:31| storeClientCopy: 4C88D268A66A52E0044352F2C277EB27, seen 0, want 0, size 4096, cb 0x8057d30, cbdata 0x104c9188
> 1998/09/11 01:53:31| cbdataLock: 0x14736b60
> 1998/09/11 01:53:31| storeClientCopy2: 4C88D268A66A52E0044352F2C277EB27
> 1998/09/11 01:53:31| storeClientCopy2: Need to open swap in file
> 1998/09/11 01:53:31| storeSwapInStart: called for 0103E03D 4C88D268A66A52E0044352F2C277EB27
> 1998/09/11 01:53:31| storeSwapInValidateComplete: Opening /usr/local/squid/cache2/03/E0/0003E03D
>
> Ok, now its opened the file...
>
> 1998/09/11 01:53:31| comm_poll: 0 sockets ready
> 1998/09/11 01:53:31| 6150: 1 -> 1
> 1998/09/11 01:53:31| OPEN of /usr/local/squid/cache2/03/E0/0003E03D to FD 68
> 1998/09/11 01:53:31| DONE: 68 -> 0
> 1998/09/11 01:53:31| file_open: FD 68
> 1998/09/11 01:53:31| fd_open FD 68 /usr/local/squid/cache2/03/E0/0003E03D
> 1998/09/11 01:53:31| storeSwapInFileOpened: initialized '/usr/local/squid/cache2/03/E0/0003E03D' for 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
>
> Grabs some headers...
>
> 1998/09/11 01:53:31| storeClientReadHeader: FD 68, len 4096
> 1998/09/11 01:53:31| storeClientReadHeader: copying 3972 bytes of body
> 1998/09/11 01:53:31| cleaning hdr: 0x8ecee78 owner: 2
> 1998/09/11 01:53:31| init-ing hdr: 0x8ecee78 owner: 2
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 33
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 9
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 20
> 1998/09/11 01:53:31| parsing hdr: (0x8ecee78)
> Server: Netscape-Enterprise/2.01
> Date: Tue, 08 Sep 1998 06:04:11 GMT
> Content-length: 5178
> Content-type: text/html
>
> 1998/09/11 01:53:31| creating entry 0x147160b0: near 'Server: Netscape-Enterprise/2.01'
> 1998/09/11 01:53:31| created entry 0x147160b0: 'Server: Netscape-Enterprise/2.01'
> 1998/09/11 01:53:31| 0x8ecee78 adding entry: 38 at 0
> 1998/09/11 01:53:31| creating entry 0x144e64d0: near 'Date: Tue, 08 Sep 1998 06:04:11 GMT'
> 1998/09/11 01:53:31| created entry 0x144e64d0: 'Date: Tue, 08 Sep 1998 06:04:11 GMT'
> 1998/09/11 01:53:31| 0x8ecee78 adding entry: 18 at 1
> 1998/09/11 01:53:31| creating entry 0x8e91608: near 'Content-length: 5178'
> 1998/09/11 01:53:31| created entry 0x8e91608: 'Content-Length: 5178'
> 1998/09/11 01:53:31| 0x8ecee78 adding entry: 13 at 2
> 1998/09/11 01:53:31| creating entry 0x14ccc868: near 'Content-type: text/html'
> 1998/09/11 01:53:31| created entry 0x14ccc868: 'Content-Type: text/html'
> 1998/09/11 01:53:31| 0x8ecee78 adding entry: 17 at 3
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 33
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 9
> 1998/09/11 01:53:31| 0x8ecee78 lookup for 20
> 1998/09/11 01:53:31| clientCacheHit: http://www.excite.com/entertainment/r_and_x_rated/free_images/, 3972 bytes
> 1998/09/11 01:53:31| refreshCheck: 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| refreshCheck: Matched '. 28800 50% 1329600'
> 1998/09/11 01:53:31| refreshCheck: age = 215360
> 1998/09/11 01:53:31| check_time: Thu, 10 Sep 1998 17:53:31 GMT
> 1998/09/11 01:53:31| entry->timestamp: Tue, 08 Sep 1998 06:04:11 GMT
> 1998/09/11 01:53:31| clientProcessMiss: 'GET http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| storeUnregister: called for '4C88D268A66A52E0044352F2C277EB27'
> 1998/09/11 01:53:31| commSetSelect: FD 68 type 1
> 1998/09/11 01:53:31| file_close: FD 68, really closing
> 1998/09/11 01:53:31| fd_close FD 68 /usr/local/squid/cache2/03/E0/0003E03D
>
> But when comparing dates etc, it notices that its due for purging from the
> cache?
>
> Its now a MISS. It checks ACL lists to see if bridge.q-net.net.au is
> allowed to fetch misses. It isn't...
>
> ANd generates that FORWARDING_DENIED message
>
> 1998/09/11 01:53:31| aclMatchIp: returning 0
> 1998/09/11 01:53:31| aclMatchAclList: returning 1
> 1998/09/11 01:53:31| creating rep: 0x14147e00
> 1998/09/11 01:53:31| init-ing hdr: 0x14147e38 owner: 2
> 1998/09/11 01:53:31| 0x14147e38 lookup for 33
> 1998/09/11 01:53:31| 0x14147e38 lookup for 9
> 1998/09/11 01:53:31| 0x14147e38 lookup for 20
> 1998/09/11 01:53:31| errorConvert: %U --> 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| errorConvert: %U --> 'http://www.excite.com/entertainment/r_and_x_rated/free_images/'
> 1998/09/11 01:53:31| errorConvert: %i --> '203.24.101.16'
> 1998/09/11 01:53:31| errorConvert: %T --> 'Thu, 10 Sep 1998 17:53:31 GMT'
> 1998/09/11 01:53:31| errorConvert: %h --> 'proxy1.per.wantree.com.au'
> 1998/09/11 01:53:31| errorConvert: %s --> 'Squid/1.2.beta23'
> 1998/09/11 01:53:31| errorConvert: %S --> '
> <br clear="all"> <hr noshade size=1>
> Generated Thu, 10 Sep 1998 17:53:31 GMT by proxy1.per.wantree.com.au (Squid/1.2.beta23)
> </BODY></HTML>
> '
>
> Sends that off etc, and theres another false ICP hit.
>
> Should squid 1.2 be saying it has a HIT on an object, when infact its
> about to expire it? (assuming I understood the above data properly :)
>
> Attached is the except showing all the inbetween debugging stuff. I also
> have around 20 minutes of squid -k debug archives in a cache.log if you
> want to examine it (Several FORWARDING_DENIED instances are contained in
> that 20 minutes :()
>
> | Are you using Cache Digests in you mesh?
>
> No.
>
> -----
> Roger Yerramsetti : ,-------. :
> rogery@wantree.com.au : : / / | a n t r e e I n t e r n e t :
> Network Administrator : | (_/_/`-'----------------------------- :
> Ph (08) 9221 8899 ::::: `-------' http://www.wantree.com.au ::::
>
Received on Thu Sep 10 1998 - 12:32:28 MDT