On 24/06/2008, Henrik Nordstrom <henrik_at_henriknordstrom.net> wrote:
> tis 2008-06-24 klockan 22:50 +0800 skrev Adrian Chadd:
>
> > The question is - why is Squid not timing the client-facing filedescriptors
> > out? Is there some pending reply which isn't being written back correctly?
>
>
> Good question.
>
> To answer that we need to look into in detail what is going on with the
> current request from one of those connections.
>
> The half-closed checks and defers is irrelevant. Just an effect. Squid
> is waiting for (or maybe even actively sending) the response.
>
> Regards
>
> Henrik
Hi guys.
I have another instance of a failure since I turned off half-closed-connections.
After turning on debug (and with all the half-closed rubish now
eliminated), it would seem that its related to how squid handles DNS:
########## Start of Request ##############
2008/06/25 10:57:56| fd_open FD 150 HTTP Request
2008/06/25 10:57:56| httpAccept: FD 150: accepted port 3128 client
212.85.29.10:57925
2008/06/25 10:57:56| cbdataLock: 0x9e23cc0
2008/06/25 10:57:56| comm_add_close_handler: FD 150,
handler=0x8079110, data=0x4ccdb4d0
2008/06/25 10:57:56| cbdataLock: 0x4ccdb4d0
2008/06/25 10:57:56| commSetTimeout: FD 150 timeout 300
2008/06/25 10:57:56| aclCheckFast: list: 0x9e23ad0
2008/06/25 10:57:56| aclMatchAclList: checking all
2008/06/25 10:57:56| aclMatchAcl: checking 'acl all src 0.0.0.0/0.0.0.0'
2008/06/25 10:57:56| aclMatchIp: '212.85.29.10' found
2008/06/25 10:57:56| aclMatchAclList: returning 1
2008/06/25 10:57:56| commSetSelect: FD 150 type 1
2008/06/25 10:57:56| commSetEvents(fd=150)
2008/06/25 10:57:56| comm_accept: FD 146: (11) Resource temporarily unavailable
2008/06/25 10:57:56| comm_select: timeout 8
2008/06/25 10:57:56| comm_call_handlers(): got fd=150 read_event=1
write_event=0 F->read_handler=0x8070890 F->write_handler=(nil)
2008/06/25 10:57:56| comm_call_handlers(): Calling read handler on fd=150
2008/06/25 10:57:56| clientReadRequest: FD 150: reading request...
2008/06/25 10:57:56| cbdataLock: 0x4ccdb4d0
2008/06/25 10:57:56| parseHttpRequest: Client HTTP version 1.1.
2008/06/25 10:57:56| parseHttpRequest: Method is 'GET'
2008/06/25 10:57:56| parseHttpRequest: URI is 'http://news.bbc.co.uk/'
2008/06/25 10:57:56| parseHttpRequest: req_hdr = {Accept: image/gif,
image/x-xbitmap, image/jpeg, image/pjpeg, application/vnd.ms-excel,
application/vnd.ms-powerpoint, application/msword,
application/xaml+xml, application/vnd.ms-xpsdocument,
application/x-ms-xbap, application/x-ms-application,
application/x-shockwave-flash, */*^M
Accept-Language: en-gb^M
UA-CPU: x86^M
Accept-Encoding: gzip, deflate^M
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET
CLR 2.0.50727; .NET CLR 1.1.4322; .NET CLR 3.0.04506.30)^M
Host: news.bbc.co.uk^M
Proxy-Connection: Keep-Alive^M
Cookie: BBCNewsCustomisation=promoPeriod%3A1214381942140%26show%3Afalse;
BBC-UID=a43885dbe6c77f6394acd6df8163ea8b4095ed8840d0c0ebac9d3873a373ade80Mozilla%2f4%2e0%20%28compatible%3b%20MSIE%207%2e0%3b%20Windows%20NT%205%2e1%3b%20%2eNET%20CLR%202%2e0%2e50727%3b%20%2eNET%20CLR%201%2e1%2e4322%3b%20%2eNET%20CLR%203%2e0%2e04506%2e30%29;
BBCNewsAudience=Domestic; BBCNewsAudcWght=-99^M
^M
}
2008/06/25 10:57:56| parseHttpRequest: end = {}
2008/06/25 10:57:56| parseHttpRequest: prefix_sz = 946, req_line_sz = 37
2008/06/25 10:57:56| parseHttpRequest: Request Header is
Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg,
application/vnd.ms-excel, application/vnd.ms-powerpoint,
application/msword, application/xaml+xml,
application/vnd.ms-xpsdocument, application/x-ms-xbap,
application/x-ms-application, application/x-shockwave-flash, */*^M
Accept-Language: en-gb^M
UA-CPU: x86^M
Accept-Encoding: gzip, deflate^M
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET
CLR 2.0.50727; .NET CLR 1.1.4322; .NET CLR 3.0.04506.30)^M
Host: news.bbc.co.uk^M
Proxy-Connection: Keep-Alive^M
Cookie: BBCNewsCustomisation=promoPeriod%3A1214381942140%26show%3Afalse;
BBC-UID=a43885dbe6c77f6394acd6df8163ea8b4095ed8840d0c0ebac9d3873a373ade80Mozilla%2f4%2e0%20%28compatible%3b%20MSIE%207%2e0%3b%20Windows%20NT%205%2e1%3b%20%2eNET%20CLR%202%2e0%2e50727%3b%20%2eNET%20CLR%201%2e1%2e4322%3b%20%2eNET%20CLR%203%2e0%2e04506%2e30%29;
BBCNewsAudience=Domestic; BBCNewsAudcWght=-99^M
^M
2008/06/25 10:57:56| parseHttpRequest: Complete request received
2008/06/25 10:57:56| conn->in.offset = 0
2008/06/25 10:57:56| commSetTimeout: FD 150 timeout 86400
2008/06/25 10:57:56| init-ing hdr: 0x76bd34e0 owner: 1
2008/06/25 10:57:56| parsing hdr: (0x76bd34e0)
Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg,
application/vnd.ms-excel, application/vnd.ms-powerpoint,
application/msword, application/xaml+xml,
application/vnd.ms-xpsdocument, application/x-ms-xbap,
application/x-ms-application, application/x-shockwave-flash, */*^M
Accept-Language: en-gb^M
UA-CPU: x86^M
Accept-Encoding: gzip, deflate^M
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET
CLR 2.0.50727; .NET CLR 1.1.4322; .NET CLR 3.0.04506.30)^M
Host: news.bbc.co.uk^M
Proxy-Connect
2008/06/25 10:57:56| creating entry 0x3cbc05e8: near 'Accept:
image/gif, image/x-xbitmap, image/jpeg, image/pjpeg,
application/vnd.ms-excel, application/vnd.ms-powerpoint,
application/msword, application/xaml+xml,
application/vnd.ms-xpsdocument, application/x-ms-xbap,
application/x-ms-application, application/x-shockwave-flash, */*'
2008/06/25 10:57:56| created entry 0x3cbc05e8: 'Accept: image/gif,
image/x-xbitmap, image/jpeg, image/pjpeg, application/vnd.ms-excel,
application/vnd.ms-powerpoint, application/msword,
application/xaml+xml, application/vnd.ms-xpsdocument,
application/x-ms-xbap, application/x-ms-application,
application/x-shockwave-flash, */*'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 0 at 0
2008/06/25 10:57:56| creating entry 0x35a82908: near 'Accept-Language: en-gb'
2008/06/25 10:57:56| created entry 0x35a82908: 'Accept-Language: en-gb'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 3 at 1
2008/06/25 10:57:56| creating entry 0x33557ca8: near 'UA-CPU: x86'
2008/06/25 10:57:56| created entry 0x33557ca8: 'UA-CPU: x86'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 68 at 2
2008/06/25 10:57:56| creating entry 0xbb372d8: near 'Accept-Encoding:
gzip, deflate'
2008/06/25 10:57:56| created entry 0xbb372d8: 'Accept-Encoding: gzip, deflate'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 2 at 3
2008/06/25 10:57:56| creating entry 0xace7358: near 'User-Agent:
Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET CLR 2.0.50727;
.NET CLR 1.1.4322; .NET CLR 3.0.04506.30)'
2008/06/25 10:57:56| created entry 0xace7358: 'User-Agent: Mozilla/4.0
(compatible; MSIE 7.0; Windows NT 5.1; .NET CLR 2.0.50727; .NET CLR
1.1.4322; .NET CLR 3.0.04506.30)'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 50 at 4
2008/06/25 10:57:56| creating entry 0x491cede0: near 'Host: news.bbc.co.uk'
2008/06/25 10:57:56| created entry 0x491cede0: 'Host: news.bbc.co.uk'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 27 at 5
2008/06/25 10:57:56| creating entry 0x46c64e30: near
'Proxy-Connection: Keep-Alive'
2008/06/25 10:57:56| created entry 0x46c64e30: 'Proxy-Connection: Keep-Alive'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 41 at 6
2008/06/25 10:57:56| creating entry 0x44be7ff8: near 'Cookie:
BBCNewsCustomisation=promoPeriod%3A1214381942140%26show%3Afalse;
BBC-UID=a43885dbe6c77f6394acd6df8163ea8b4095ed8840d0c0ebac9d3873a373ade80Mozilla%2f4%2e0%20%28compatible%3b%20MSIE%207%2e0%3b%20Windows%20NT%205%2e1%3b%20%2eNET%20CLR%202%2e0%2e50727%3b%20%2eNET%20CLR%201%2e1%2e4322%3b%20%2eNET%20CLR%203%2e0%2e04506%2e30%29;
BBCNewsAudience=Domestic; BBCNewsAudcWght=-99'
2008/06/25 10:57:56| created entry 0x44be7ff8: 'Cookie:
BBCNewsCustomisation=promoPeriod%3A1214381942140%26show%3Afalse;
BBC-UID=a43885dbe6c77f6394acd6df8163ea8b4095ed8840d0c0ebac9d3873a373ade80Mozilla%2f4%2e0%20%28compatible%3b%20MSIE%207%2e0%3b%20Windows%20NT%205%2e1%3b%20%2eNET%20CLR%202%2e0%2e50727%3b%20%2eNET%20CLR%201%2e1%2e4322%3b%20%2eNET%20CLR%203%2e0%2e04506%2e30%29;
BBCNewsAudience=Domestic; BBCNewsAudcWght=-99'
2008/06/25 10:57:56| 0x76bd34e0 adding entry: 22 at 7
2008/06/25 10:57:56| 0x76bd34e0 lookup for 20
2008/06/25 10:57:56| clientSetKeepaliveFlag: http_ver = 1.1
2008/06/25 10:57:56| clientSetKeepaliveFlag: method = GET
2008/06/25 10:57:56| 0x76bd34e0 lookup for 41
2008/06/25 10:57:56| 0x76bd34e0: joining for id 41
2008/06/25 10:57:56| 0x76bd34e0: joined for id 41: Keep-Alive
2008/06/25 10:57:56| 0x76bd34e0 lookup for 52
2008/06/25 10:57:56| 0x76bd34e0 lookup for 41
2008/06/25 10:57:56| 0x76bd34e0: joining for id 41
2008/06/25 10:57:56| 0x76bd34e0: joined for id 41: Keep-Alive
2008/06/25 10:57:56| 0x76bd34e0 lookup for 59
2008/06/25 10:57:56| cbdataLock: 0x9e26218
2008/06/25 10:57:56| cbdataLock: 0x4ccdb4d0
2008/06/25 10:57:56| cbdataLock: 0x7537e998
2008/06/25 10:57:56| cbdataValid: 0x9e26218
2008/06/25 10:57:56| aclCheck: checking 'http_access allow
private_address_excludes'
2008/06/25 10:57:56| aclMatchAclList: checking private_address_excludes
2008/06/25 10:57:56| aclMatchAcl: checking 'acl
private_address_excludes dst 172.17.2.0/24'
2008/06/25 10:57:56| ipcache_gethostbyname: 'news.bbc.co.uk', flags=1
2008/06/25 10:57:56| ipcache_nbgethostbyname: Name 'news.bbc.co.uk'.
2008/06/25 10:57:56| ipcache_nbgethostbyname: MISS for 'news.bbc.co.uk'
2008/06/25 10:57:56| cbdataLock: 0xbe708e0
2008/06/25 10:57:56| aclMatchAcl: Can't yet compare
'private_address_excludes' ACL for 'news.bbc.co.uk'
2008/06/25 10:57:56| aclMatchAclList: no match, returning 0
2008/06/25 10:57:56| ipcache_nbgethostbyname: Name 'news.bbc.co.uk'.
2008/06/25 10:57:56| ipcache_nbgethostbyname: MISS for 'news.bbc.co.uk'
This is the last log entry related to the connection. It would seem
that requests where IP records are stored within the ipcache still
work OK, but in this instance no IP record was found in the cache.
Does this provide any further clues?
squidclient mgr:filedescriptors does not show any outbound connections
relating to my request - I dont think its getting that far. I would
expect to see some log messages about sending DNS packets to our DNS
server (which is definatley working, as the other 29 squid servers in
this cluster still work fine!).
The last line (ipcache_nbgethostbyname: MISS) is in ipcache.c, where
it then goes on to call idnsALookup(), however no further debug
messages are shown so my guess is that this function is returning
early - possibly because idnsCachedLookup() is returning true?
I dont know the code that well but if the entry is not in the ipcache,
then how can idnsCachedLookup return true?
Regards
-- Brad.Received on Wed Jun 25 2008 - 11:30:32 MDT
This archive was generated by hypermail 2.2.0 : Thu Jun 26 2008 - 12:00:05 MDT