[squid-users] High response times with Squid

Sat Feb 16 20:03:02 UTC 2019

You can replace them with dstdom_regex which will not trigger a PTR lookup.

Eliezer

----
Eliezer Croitoru
Linux System Administrator
Mobile: +972-5-28704261
Email: eliezer at ngtech.co.il

-----Original Message-----
From: squid-users <squid-users-bounces at lists.squid-cache.org> On Behalf Of Ahmad, Sarfaraz
Sent: Thursday, February 14, 2019 12:39
To: Amos Jeffries <squid3 at treenet.co.nz>; squid-users at lists.squid-cache.org
Subject: Re: [squid-users] High response times with Squid

Hi again,
I made some progress on this.
To reiterate, I am peeking at the SNI and then bump all connections to the origin server in context of this problem. ( the origin server is seamless.com )

Here are the new findings ,
1) The 20sec lag is noticed even when I splice the connection.
2) It 99% has to do with the following slow ACL acl.

acl deny_explicit_dstdomain dstdomain "/etc/squid/acls/deny_explicit_dstdomain"

I see PTR lookups failing when Squid tries to validate my ACLs. When I disable that ACL, the 20second lag is gone. So I am pretty confident that subsequent PTR lookups are causing the delay here.
I don't see a configuration directive with which I can configure how many times Squid retries the lookup.
I see one that sets the timeout though (dns_timeout  defaults 30 seconds).

Could you guys give me some pointers on what could be happening here ?

Regards,
Ahmad

-----Original Message-----
From: squid-users <squid-users-bounces at lists.squid-cache.org> On Behalf Of Amos Jeffries
Sent: Saturday, February 9, 2019 10:20 AM
To: squid-users at lists.squid-cache.org
Subject: Re: [squid-users] High response times with Squid

On 8/02/19 7:30 pm, Ahmad, Sarfaraz wrote:
> Hi,
> 
>  
> 
> I am using Squid 4.5 with WCCP. Intercepting SSL by peeking at step1 
> and then deciding to either splice or bump upon the SNI.
> 
> I am noticing a weird behavior for some of my TCP connections.  Squid 
> is taking over 20s to decide what do with the ClientHello sent by the 
> browser. It is only after 20s that it decides to send out a 
> ClientHello to the origin server and at the same time reply to the 
> client with a ServerHello.
> 
> This behavior is hard to reproduce and only some clients are affected.
> 
>  
> 
> I will try to summarize what I see in cache.log with ALL, 6 debug options.
> 
>  
> 
> 1)      Squid's INTERCEPTION thread/program receives a TCP SYN from 
> workstation.
> 
> 2019/02/06 17:23:19.070 kid1| 89,5| Intercept.cc(405) Lookup: address
> BEGIN: me/client= *<SQUID_IP>:*23129, destination/me=
> *<CLIENT/BROWSER_IP>:*58232
> 

No. This is looking up the original TCP dst-IP:port in the kernel NAT tables.

>  
> 
> 2)      Squid becomes the origin server and sets up the TCP connection.
> 

No. The local= log values are a simple statement of the TCP packet values received from the NAT system at (1). Squid is an MITM in this setup, so the client *thinks* it is talking to the origin.

Being an MITM Squid is designed to operate as transparently as possible, but at no time has the abilities of the origin server.

> 2019/02/06 17:23:19.070 kid1| 5,5| AsyncCall.cc(93) ScheduleCall:
> TcpAcceptor.cc(339) will call
> httpsAccept(local*=<ORIGIN_SERVER_ON_THE_INTERNET>*:443
> remote=*<CLIENT/BROWSER_IP>:*58232 FD 40 flags=33, MXID_1101703) 
> [call34733258]
> 

...
> 
> 8)      No ServerHello has been sent back to the client yet, Squid 
> starts a TCP connection with the origin server
> 
> 2019/02/06 17:23:19.110 kid1| 5,4| AsyncJob.cc(123) callStart:
> Comm::ConnOpener status in: [ job2971439]
> 
> 2019/02/06 17:23:19.110 kid1| 5,5| ConnOpener.cc(350) doConnect:
> local=0.0.0.0 remote*=<ORIGIN_SERVER_ON_THE_INTERNET>:*443 flags=1:
> Comm::OK - connected
> 
> 2019/02/06 17:23:19.110 kid1| 5,4| ConnOpener.cc(155) cleanFd:
> local=0.0.0.0 remote=<*ORIGIN_SERVER_ON_THE_INTERNET*>:443 flags=1 
> closing temp FD 50
> 
>  
> 
> 9)      Squid starts a TLS session with the remote/origin server, 
> sends the ClientHello. A total of 0.4 seconds in Squid sending 
> clienthello to origin server. This is probably when Squid decides to 
> send back the ServerHello to the browser.

Don't guess. Check.

Either you have step2 / client-first bumping - in which case the Squid serverHello would have been sent to the client at (7).

Or, you have step3 / server-first bumping - in which case Squid cannot send a serverHello to the client until it has received the origin's serverHello. Which still has not yet been received despite your trace ending here.

...
> 
> 2019/02/06 17:23:19.111 kid1| 83,5| PeerConnector.cc(123) initialize:
> local=*<SQUID_IP>*:44498 remote=*<ORIGIN_SERVER_ON_THE_INTERNET>*:443 
> FD
> 50 flags=1, session=0x14899390
> 
>  
> 
> So somewhere between Step 8 and Step 9, Squid is taking over 20s.
> 

There is only 1 millisecond between those steps.

The client connection was received at 17:23:19.070, your (9) finished at
17:23:19.111 -> so there is your 0.41 seconds. If there is any 20s gap for this transaction it is later in the log part you have not shown.

> 
> What could possibly be keeping it busy ?
> 

Other transactions? Nothing?

What is going on at (9) is *preparing* to send a TLS clientHello. At the point your log stops it still has not actually been written to the network.

There is actually still a good half of the SSl-Bump process to happen:
 - assemble the Squid clientHello bytes,
 - send that to origin
 - receive origin serverHello
 - validate the origin details
 - HTTP fetch missing certificates (if any)
   - re-validate the origin details (repeat fetch as necessary)
 - formulate the Squid serverHello
 - send that to client
 - receive HTTP request over the secured client connection

... then all the HTTP(S) message processing on the resulting connection.

> 
> UPDATE: This problem statement seems local to a few websites. Outside 
> of the proxy, those websites quite quickly as is expected.
> 
> 
> Any thoughts on where to look ?  other bits and pieces I could check ?
>  I have jumbo frames enabled (9000 bytes) but am running the proxies 
> at
> L2 1500 MTU.
> 

It is hard to say without also knowing your squid.conf settings and what sites specifically you are having trouble with,

Could be anything from a packet loss in some remote router halfway around the world. To misconfiguration of something in your network. To misconfiguration by the origin server admin.

IMO that last one is most likely if the behaviour is only delay (not
errors) and with only certain domains.

Amos
_______________________________________________
squid-users mailing list
squid-users at lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
_______________________________________________
squid-users mailing list
squid-users at lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users