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

[Amos Jeffries]

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