Re: [squid-users] Weird 3 second delay between Squid and F5 LB (reverse proxy) (RESOLUTION)

Top posting.

The issue was with the Load Balancer closing the connection and the
client thinking that the port was still open.. F5 did an amazing job
with deciphering my dumps and following the packets. They stepped up
and said "it does in fact look like our system and not Squid"

Looking through cache01-new, every instance of a 3 second delay that I
find, I see where 10.13.200.42 sends the SYN, which is sent through
the BIG-IP to 10.13.200.153. In each instance, I find that
10.13.200.153, rather than replying to the SYN with a SYN-ACK, simply
sends an ACK. This, bing incorrect, gets a RST response from
10.13.200.42. After all, 10.13.200.42 was expecting SYN-ACK, not ACK.
 After a three second delay, 10.13.200.42 initiates the handshake
again, and this time 10.13.200.153 sends the SYN-ACK response, which
allows the handshake to carry on. I had iniitially thought that this
was the fault of 10.13.200.42, but looking over the w04-new tcpdump,
and matching up the delay packets, it's very clear that there is no
SYN-ACK, resulting in this 3 second delay.

As to why 10.13.200.153 would respond to a SYN with just an ACK, I
believe that this may be due to a port reuse issue. The server
believes that port to still be in use, while the BIG-IP believes it to
be closed. To get around this, I would suggest the use of
incrementing autoport, where the BIG-IP does not try to use the same
ephemeral port that the client uses, but rather makes use of some
other ephemeral port. "

Just wanted to close this out, I didn't think it was the Squid box but
had to be sure. So I'm good to go!

On 7/27/07, Adrian Chadd <adrian@creative.net.au> wrote:
> Have you looked at it through tcpdump?
> Those sorts of delays could be simple stuff like forward/reverse
> DNS..
>
>
> Adrian
>
> On Fri, Jul 27, 2007, Tory M Blue wrote:
> > I'm not sure what is going on and have done so much tracing that I've
> > just probably confused things more then anything else.
> >
> > i'm running Squid Cache: Version 2.6.STABLE12, on Fedora Core 6.
> >
> > It's configured to point to a single parent (which is a Virtual IP on
> > the LB) with multiple servers sitting behind that virtual (so yes a
> > pool).
> >
> > If i run wget's, socket scrpts etc, against squid pointing to a single
> > host, or have all 4 hosts listed as parents, there is no issue.
> >
> > If I have squid pointing at the above mentioned VIP I see a 3 second
> > delay every x connections, can be the 9th, 30th or 100th connection
> > (again the 3 second delays are very random, but very bothersome).
> >
> > Another point of interest, running thru a Netapp Cache there are zero delays..
> >
> >
> > Socket level test:
> >
> > Fri Jul 27 08:56:53 2007: Iteration #28
> > Fri Jul 27 08:56:53 2007: Connecting to localhost:80...
> > Fri Jul 27 08:56:53 2007: Connected.
> > Fri Jul 27 08:56:53 2007: Sending request...
> > Fri Jul 27 08:56:53 2007: Sent.
> > Fri Jul 27 08:56:53 2007: Receiving response... <--- 3 second delay..
> > Fri Jul 27 08:56:56 2007: Received complete response.
> > Fri Jul 27 08:56:56 2007: Closing socket.
> > Fri Jul 27 08:56:56 2007: Socket closed.
> >
> > Squid http debug: 3 second delay at end
> > ----------------------------------------
> > 2007/07/26 15:36:35| getMaxAge:
> > 'http://host/abc/directorytest/c/i-1.JPG?rand=859749'
> > 2007/07/26 15:36:35| ctx: enter level 0:
> > 'http://host/abc/directorytest/c/i-1.JPG?rand=859749'
> > 2007/07/26 15:36:35| refreshCheck:
> > 'http:/host/abc/directorytest/c/i-1.JPG?rand=859749'
> > 2007/07/26 15:36:35| STALE: expires 1185489395 < check_time 1185489455
> > 2007/07/26 15:36:35| Staleness = 60
> > 2007/07/26 15:36:35| refreshCheck: Matched '<none> 0 20% 259200'
> > 2007/07/26 15:36:35| refreshCheck: age = 60
> > 2007/07/26 15:36:35| check_time: Thu, 26 Jul 2007 22:37:35 GMT
> > 2007/07/26 15:36:35| entry->timestamp: Thu, 26 Jul 2007 22:36:35 GMT
> > 1185489395.994 SWAPOUT 00 00081DFD 741C0A705149FFD54F8CE6B6B4486D77
> > 200 1185489396 1185383126 1185489396 image/jpeg 42492/42492 GET
> > http://host/abc/directorytest/c/i-1.JPG?
> > 2007/07/26 15:36:38| ctx: exit level 0 <--- shows the 3 second delay
> >
> >
> > More Squid debug (different times) 3 second delay at end
> > -------------------------------------------------
> > 2007/07/26 15:06:54| fwdStateFree: 0x85b9388
> > 2007/07/26 15:06:54| fwdStart:
> > 'http://host/abc/directorytest/c/i-1.JPG?rand=279660'
> > 2007/07/26 15:06:54| fwdStartComplete:
> > http://host/abc/directorytest/c/i-1.JPG?rand=279660
> > 2007/07/26 15:06:54| fwdConnectStart:
> > http://host/abc/directorytest/c/i-1.JPG?rand=279660
> > 2007/07/26 15:06:54| fwdConnectStart: got addr 0.0.0.0, tos 0
> > 2007/07/26 15:07:03| fwdConnectDone: FD 17:
> > 'http://host/abc/directorytest/c/i-1.JPG?rand=279660'
> > 2007/07/26 15:07:03| fwdDispatch: FD 16: Fetching 'GET
> > http://host/abc/directorytest/c/i-1.JPG?rand=279660'
> > 2007/07/26 15:07:03| fwdComplete:
> > http://hostabc/directorytest/c/i-1.JPG?rand=279660
> > status 200
> > 2007/07/26 15:07:03| fwdReforward:
> > http://hostabc/directorytest/c/i-1.JPG?rand=279660?
> > 2007/07/26 15:07:03| fwdReforward: No, ENTRY_FWD_HDR_WAIT isn't set
> > 2007/07/26 15:07:03| fwdComplete: not re-forwarding status 200
> > 1185487623.236 SWAPOUT 00 0008077B 8AB49FB3B897FB721E06A8ED91EE1AF 200
> > 1185487623 1185383126 1185487623 image/jpeg 42492/42492 GET
> > http://host/abc/directorytest/c/i-1.JPG?
> > 2007/07/26 15:07:03| fwdServerClosed: FD 17
> > http://host/abc/directorytest/c/i-1.JPG?rand=279660
>
> --
> - Xenion - http://www.xenion.com.au/ - VPS Hosting - Commercial Squid Support -
> - $25/pm entry-level bandwidth-capped VPSes available in WA -
>
Received on Fri Aug 17 2007 - 14:11:18 MDT