Hi,
Many thanks for the reply. I've run the latest 3.2 snapshot on a standalone server and have generated a cache.log and corresponding access.log files.
I've got a number of entries in the file.
1). http://dummyhost5678.hull.ac.uk/fred.txt
This as you can guess is a nonexistent URL used to healthcheck a web cache by our hardware load balancer. I'm expecting a 503 status code to come back as it doesn't exist.
Usually this occurs and you can see a response time of something in the order of 30 msec (?). However you also see the NONE_ABORTED:HIER_NONE request status and a response time of 4987 msecs which I'm fairly sure shouldn't happen.
2). doing a grep of ( sure there'll be a more elegant way of doing this)
grep response_time\>[123456789][123456789][123456789][123456789][123456789] access.log.trace
you get a whole batch of really long response times. Lurking around in there are www.bbc.co.uk healthcheck requests from the load balancer with queries from a client as well that also time out.
<squid_rec source_ip="150.237.129.18" client_ip="-" cache="150.237.85.227" time="1328845687.303" real_cache="150.237.85.247"><source_ip>150.237.129.18</source_ip><client_ip>-</client_ip><user_login>-</user_login><user_ident>-</user_ident><user_name>-</user_name><date_time>10/Feb/2012:03:48:07 +0000</date_time><request_method>GET</request_method><url>http://rssnewsapps.ziffdavis.com/eweekmac.xml</url><protocol>HTTP/1.1</protocol><status_code>200</status_code><reply_size>4378</reply_size><request_status>TCP_MISS:HIER_DIRECT</request_status><response_time>111160</response_time></squid_rec>
<squid_rec source_ip="150.237.140.32" client_ip="-" cache="150.237.84.13" time="1328845702.136" real_cache="150.237.85.247"><source_ip>150.237.140.32</source_ip><client_ip>-</client_ip><user_login>-</user_login><user_ident>-</user_ident><user_name>-</user_name><date_time>10/Feb/2012:03:48:22 +0000</date_time><request_method>GET</request_method><url>http://news.google.com/?</url><protocol>HTTP/1.1</protocol><status_code>200</status_code><reply_size>49331</reply_size><request_status>TCP_CLIENT_REFRESH_MISS:HIER_DIRECT</request_status><response_time>111752</response_time></squid_rec>
<squid_rec source_ip="150.237.128.66" client_ip="-" cache="150.237.84.13" time="1328845747.54" real_cache="150.237.85.247"><source_ip>150.237.128.66</source_ip><client_ip>-</client_ip><user_login>-</user_login><user_ident>-</user_ident><user_name>-</user_name><date_time>10/Feb/2012:03:49:07 +0000</date_time><request_method>GET</request_method><url>http://www.google.co.uk/</url><protocol>HTTP/1.1</protocol><status_code>0</status_code><reply_size>0</reply_size><request_status>NONE_ABORTED:HIER_NONE</request_status><response_time>59929</response_time></squid_rec>
<squid_rec source_ip="150.237.129.253" client_ip="-" cache="150.237.84.13" time="1328845748.831" real_cache="150.237.85.247"><source_ip>150.237.129.253</source_ip><client_ip>-</client_ip><user_login>-</user_login><user_ident>-</user_ident><user_name>-</user_name><date_time>10/Feb/2012:03:49:08 +0000</date_time><request_method>CONNECT</request_method><url>d.dropbox.com:443</url><protocol>HTTP/1.1</protocol><status_code>200</status_code><reply_size>5030</reply_size><request_status>TCP_MISS:HIER_DIRECT</request_status><response_time>61367</response_time></squid_rec>
I'll probably have a peek at the log files myself to see if i can find something but I'll zip them up and submit a bug as well.
Rgds
Alex
On 9 Feb 2012, at 01:48, Alex Rousskov wrote:
> On 02/08/2012 05:14 AM, alex sharaz wrote:
>
>> I then downloaded the latest patch release 3.2.0.15......11508 and
>> installed it on the test server. With this release, again everything
>> seemed ok and a browser connecting to squid would get the 1st page. Any
>> further attempts would result in a seriously long delay before anything
>> appeared in the browser. A netstat -a would show a connection from the
>> client to squid access.log would show nothing and then eventually (sorry
>> I've XML'ized the logs) something of the form shown below.
>>
>> <squid_rec source_ip="150.237.129.18" client_ip="-"
>> cache="150.237.85.197" time="1328683548.416"
>> real_cache="150.237.85.197"><source_ip>150.237.129.18</source_ip><client_ip>-</client_ip><user_login>-</user_login><user_ident>-</user_ident><user_name>-</user_name><date_time>08/Feb/2012:06:45:48
>> +0000</date_time><request_method>GET</request_method><url>http://www.mozilla.org/img/covehead/divider-notch.jpg</url><protocol>HTTP/1.1</protocol><status_code>0</status_code><reply_size>0</reply_size><request_status>NONE_ABORTED:HIER_NONE</request_status><response_time>22881</response_time></squid_rec>
>>
>>
>>
>> The only thing that's changed is the release of squid used.
>>
>> FWIW I've re-enabled ipv6 on the box and removed the --disable-ipv6
>> option from the configure to no avail.
>>
>> Bit stuck as to what to look at next, any suggestions?
>
> If you can reproduce the "seriously long delay" problem with just a few
> requests, then I recommend enabling full debugging (debug options
> ALL,9), starting Squid from scratch, submitting those requests, and
> filing a bug report with the resulting cache.log. If you identify the
> URL that has experienced the delay, it would help others to find the
> troubling transaction in the logs.
>
> You could analyze the log yourself as well, of course. It is often easy
> to spot the place where the delay happens, especially if you use the
> scripts to trace isolated transactions. What to do next depends on where
> the identified delay source.
>
>
> HTH,
>
> Alex.
==========
Time for another Macmillan Cancer Support event. This time its the 12 day Escape to Africa challenge
View route at http://maps.google.co.uk/maps/ms?ie=UTF8&hl=en&msa=0&msid=203779866436035016780.00049e867720273b73c39&z=8
Please sponsor me at http://www.justgiving.com/Alex-Sharaz
Received on Fri Feb 10 2012 - 04:06:33 MST
This archive was generated by hypermail 2.2.0 : Fri Feb 10 2012 - 12:00:08 MST
