[squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

[Ahmad, Sarfaraz]

>> As late as it can be done. How late that is depends on your SSL-Bump setup, any ICAP or other changes being made to the fake-CONNECT request, maybe even your cache contents.
All I am doing is peeking at Step1 (Client SNI) and then bumping vast majority of connections, splicing very few. Caching is completely disabled.

>> The client "<ip>" opened a TCP connection to 173.194.142.186:443 - which was intercepted and delivered to this Squid. The client disconnected after 78 seconds.
This doesn't explain why I saw 20+secs for TCP in Chrome dev tools'.  From Chrome's dev tools, it looks like setting up TLS did not take long but setting up TCP surely did.

 >> We know that the server IP:port should be 173.194.142.186:443 because those are the details on the CONNECT message URI. Squid has not gone far enough into the processing of that message to identify that detail.
What would usually be the next step here? Could DNS be involved ?


-----Original Message-----
From: Amos Jeffries <squid3 at treenet.co.nz> 
Sent: Tuesday, August 7, 2018 11:14 PM
To: Ahmad, Sarfaraz <Sarfaraz.Ahmad at deshaw.com>; squid-users at lists.squid-cache.org
Subject: Re: [squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

On 08/08/18 05:15, Ahmad, Sarfaraz wrote:
>>> Your guess is wrong. The TCP level setup is only between Squid and the client. It has to have completed before the TLS stuff can begin.
> So when does Squid start setting up the TCP connection with the origin server ? After setting up a TCP connection with client and identifying it to be TLS ?

As late as it can be done. How late that is depends on your SSL-Bump setup, any ICAP or other changes being made to the fake-CONNECT request, maybe even your cache contents.

Anyhow, there is no sign of a server connection existing. So whatever is happening is one of the early parts of TLS handshake.


> 
> What would this log message likely mean then ? I was reading that as 78477ms was the time it took for Squid to connect to 173.194.142.186 on port 443 and Squid and client(not the origin server) had already established a TCP connection beforehand (while it(squid) tries connecting to the remote server on port 443).
> 1533612202.312  78477 <ip> NONE_ABORTED/000 0 CONNECT 
> 173.194.142.186:443 - HIER_NONE/- -
> 

The client "<ip>" opened a TCP connection to 173.194.142.186:443 - which was intercepted and delivered to this Squid. The client disconnected after 78 seconds.
 That is all that can be known about what did happen from this log entry.

The list of things which did not (or could not have) happen is longer:

No server connection was made.
No bytes delivered to the client.
 and a lot of other things cannot have happened.


> That would imply two things.
> 1) It took a lot of time for clients to set up a TCP connection with 
> Squid given Chrome's dev tools

The client->Squid TCP setup seems to be completed. Either Squid is waiting for TLS handshake from the client to arrive, or something is hung in the processing of the clientHello stages.

NP: the 0-bytes number in the log is how much Squid delivered to the client. There may be some bytes the client delivered to Squid which are not accounted.



> 2) Second, Squid took a while to establish a connection with origin server.

I don't think Squid got that far. There is no server IP following the "HEIR_NONE/". The "-" part specifically says there is no known server IP.

We know that the server IP:port should be 173.194.142.186:443 because those are the details on the CONNECT message URI. Squid has not gone far enough into the processing of that message to identify that detail.


> 
> Moreover, my ICAP settings look like this, icap_service localicap 
> reqmod_precache icap://127.0.0.1:1345/reqmod bypass=on routing=off 
> on-overload=wait
> 
> ICAP would come into the picture only after I see a GET request in the access.log, right?

ICAP should be passed any HTTP request. Since Squid is handling the CONNECT message the ICAP should be invoked for them as well. I don't recall of it actually is or not.

Also, note that at no point have I confirmed that is is ICAP being the problem (nor ruled it out). You are the one focusing on that possibility. There are other possibilities such as SSL-Bump issues, http_access delays and the like. Even client_delay_pool's may be the problem.


Amos