On 24/06/2008, Henrik Nordstrom <[EMAIL PROTECTED]> 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.
