Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Ahmad, Sarfaraz

Hi,

 

I am WCCPv2 for redirecting traffic to Squid.

Intermittently I see these messages in access.log and the internet for clients goes away.

 

1533612202.312  79102 <ip> NONE_ABORTED/000 0 CONNECT 198.22.156.64:443 - HIER_NONE/- -

1533612202.312  82632 <ip> NONE_ABORTED/000 0 CONNECT 173.194.142.186:443 - HIER_NONE/- -

1533612202.312  16030 <ip> NONE_ABORTED/000 0 CONNECT 172.217.15.67:443 - HIER_NONE/- -

1533612202.312  78477 <ip> NONE_ABORTED/000 0 CONNECT 173.194.142.186:443 - HIER_NONE/- -

 

But I can access internet on the host running squid itself just fine yet Squid reports those messages with high response times (the second column).

I gather from http://lists.squid-cache.org/pipermail/squid-users/2016-February/009295.html that HIER_NONE implies no remote server was contacted. (or could be contacted ?)

 

Note: I replaced internal IP addresses with <ip> tag. Please don’t get confused.

 

We use an ICAP service. Could that play a role here ?

Any thoughts ?

 

Regards,

Sarfaraz


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Amos Jeffries
Administrator
On 07/08/18 21:55, Ahmad, Sarfaraz wrote:
> Hi,
>
>  
>
> I am WCCPv2 for redirecting traffic to Squid.
>

Squid version?

> Intermittently I see these messages in access.log and the internet for
> clients goes away.
>
>  
>
> 1533612202.312  79102 <ip> NONE_ABORTED/000 0 CONNECT 198.22.156.64:443
> - HIER_NONE/- -
>
> 1533612202.312  82632 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
> 1533612202.312  16030 <ip> NONE_ABORTED/000 0 CONNECT 172.217.15.67:443
> - HIER_NONE/- -
>
> 1533612202.312  78477 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
>  
>
> But I can access internet on the host running squid itself just fine yet
> Squid reports those messages with high response times (the second column).
>
...>  
>
> We use an ICAP service. Could that play a role here ?

A lot of things *might* play a role there.

>
> Any thoughts ?

Trace the traffic.

What did the client actually send to Squid?
  It's probably not a port-80 style CONNECT request.

What does Squid send back to the client?

Does Squid complete the TLS handshake?

What are your SSL-Bump settings?


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Ahmad, Sarfaraz
I cannot reproduce this. This is intermittent.  In Chrome's dev tools, it appeared to take over 20 secs to setup the TCP connection.
I am SSL bumping all TLS connections unless they match certain ACLs. So it is safe to assume that the vast majority of the traffic was bumped.

I don't see any TLS handshake failure messages in cache.log. I think the access.log messages I posted earlier are fake CONNECT requests created using TCP-level info (the response time logged there is directly proportionate to what I see in Chrome's dev tools). Guessing that Squid would send TCP SYN-ACK only after it receives SYN-ACK from remote/origin server.
I don’t think ICAP(reqmod) would come into the picture yet either (assuming that even the TCP connections have not been set up yet) so that is safe to rule out. Am I right here ?

Also restarting squid service fixed this.  I had a python script running in the background that was able to GET a webpage using requests module(timeout set to 30) but Squid apparently couldn't even set up a TCP connection.

- Sarfaraz



-----Original Message-----
From: squid-users <[hidden email]> On Behalf Of Amos Jeffries
Sent: Tuesday, August 7, 2018 6:04 PM
To: [hidden email]
Subject: Re: [squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

On 07/08/18 21:55, Ahmad, Sarfaraz wrote:
> Hi,
>
>  
>
> I am WCCPv2 for redirecting traffic to Squid.
>

Squid version?

> Intermittently I see these messages in access.log and the internet for
> clients goes away.
>
>  
>
> 1533612202.312  79102 <ip> NONE_ABORTED/000 0 CONNECT
> 198.22.156.64:443
> - HIER_NONE/- -
>
> 1533612202.312  82632 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
> 1533612202.312  16030 <ip> NONE_ABORTED/000 0 CONNECT
> 172.217.15.67:443
> - HIER_NONE/- -
>
> 1533612202.312  78477 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
>  
>
> But I can access internet on the host running squid itself just fine
> yet Squid reports those messages with high response times (the second column).
>
...>  
>
> We use an ICAP service. Could that play a role here ?

A lot of things *might* play a role there.

>
> Any thoughts ?

Trace the traffic.

What did the client actually send to Squid?
  It's probably not a port-80 style CONNECT request.

What does Squid send back to the client?

Does Squid complete the TLS handshake?

What are your SSL-Bump settings?


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Sticher, Jascha
Hi,

most times we encountered this error message it had something to do with IPv4 DNS queries being answered too slowly or not at all (as in: only AAAA-records in the reply). If this occurring with some sites only, that could be the case.

You could verify this by sniffing your DNS queries from the squid. We solved >99% of these error with the following two lines - a couple of sites needed entries in /etc/hosts, because their nameservers were broken.


> dns_timeout 10 seconds
> forward_max_tries 25


Kind regards,

Jascha Sticher


-----Ursprüngliche Nachricht-----
Von: squid-users <[hidden email]> Im Auftrag von Ahmad, Sarfaraz
Gesendet: Dienstag, 7. August 2018 16:15
An: Amos Jeffries <[hidden email]>; [hidden email]
Betreff: Re: [squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

I cannot reproduce this. This is intermittent.  In Chrome's dev tools, it appeared to take over 20 secs to setup the TCP connection.
I am SSL bumping all TLS connections unless they match certain ACLs. So it is safe to assume that the vast majority of the traffic was bumped.

I don't see any TLS handshake failure messages in cache.log. I think the access.log messages I posted earlier are fake CONNECT requests created using TCP-level info (the response time logged there is directly proportionate to what I see in Chrome's dev tools). Guessing that Squid would send TCP SYN-ACK only after it receives SYN-ACK from remote/origin server.
I don’t think ICAP(reqmod) would come into the picture yet either (assuming that even the TCP connections have not been set up yet) so that is safe to rule out. Am I right here ?

Also restarting squid service fixed this.  I had a python script running in the background that was able to GET a webpage using requests module(timeout set to 30) but Squid apparently couldn't even set up a TCP connection.

- Sarfaraz



-----Original Message-----
From: squid-users <[hidden email]> On Behalf Of Amos Jeffries
Sent: Tuesday, August 7, 2018 6:04 PM
To: [hidden email]
Subject: Re: [squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

On 07/08/18 21:55, Ahmad, Sarfaraz wrote:
> Hi,
>
>  
>
> I am WCCPv2 for redirecting traffic to Squid.
>

Squid version?

> Intermittently I see these messages in access.log and the internet for
> clients goes away.
>
>  
>
> 1533612202.312  79102 <ip> NONE_ABORTED/000 0 CONNECT
> 198.22.156.64:443
> - HIER_NONE/- -
>
> 1533612202.312  82632 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
> 1533612202.312  16030 <ip> NONE_ABORTED/000 0 CONNECT
> 172.217.15.67:443
> - HIER_NONE/- -
>
> 1533612202.312  78477 <ip> NONE_ABORTED/000 0 CONNECT
> 173.194.142.186:443 - HIER_NONE/- -
>
>  
>
> But I can access internet on the host running squid itself just fine
> yet Squid reports those messages with high response times (the second column).
>
...>  
>
> We use an ICAP service. Could that play a role here ?

A lot of things *might* play a role there.

>
> Any thoughts ?

Trace the traffic.

What did the client actually send to Squid?
  It's probably not a port-80 style CONNECT request.

What does Squid send back to the client?

Does Squid complete the TLS handshake?

What are your SSL-Bump settings?


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Amos Jeffries
Administrator
In reply to this post by Ahmad, Sarfaraz
On 08/08/18 02:14, Ahmad, Sarfaraz wrote:

> I cannot reproduce this. This is intermittent.  In Chrome's dev
> tools, it appeared to take over 20 secs to setup the TCP connection.
> I am SSL bumping all TLS connections unless they match certain ACLs.
> So it is safe to assume that the vast majority of the traffic was
> bumped.
>
> I don't see any TLS handshake failure messages in cache.log. I think
> the access.log messages I posted earlier are fake CONNECT requests
> created using TCP-level info (the response time logged there is
> directly proportionate to what I see in Chrome's dev tools). Guessing
> that Squid would send TCP SYN-ACK only after it receives SYN-ACK from
> remote/origin server.

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.

The first fake-CONNECT is done after TCP connection setup to see whether
the client is allowed to perform TLS inside it - and how Squid handles
that TLS.


> I don’t think ICAP(reqmod) would come into the
> picture yet either (assuming that even the TCP connections have not
> been set up yet) so that is safe to rule out. Am I right here ?

You are right about that in relation to TCP.

But TCP is already over and done with by the time the fake-CONNECT gets
generated. So wrong about ICAP's lack of involvement - it may (or not) be.

NP: The only thing fake about the early CONNECT's is that the client did
not actually generate it. They are handled in Squid same as a regular
CONNECT message would be.

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Ahmad, Sarfaraz
>> 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 ?

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/- -

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
2) Second, Squid took a while to establish a connection with origin server.

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?

Regards,
Sarfaraz

-----Original Message-----
From: Amos Jeffries <[hidden email]>
Sent: Tuesday, August 7, 2018 9:04 PM
To: Ahmad, Sarfaraz <[hidden email]>; [hidden email]
Subject: Re: [squid-users] Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

On 08/08/18 02:14, Ahmad, Sarfaraz wrote:

> I cannot reproduce this. This is intermittent.  In Chrome's dev tools,
> it appeared to take over 20 secs to setup the TCP connection.
> I am SSL bumping all TLS connections unless they match certain ACLs.
> So it is safe to assume that the vast majority of the traffic was
> bumped.
>
> I don't see any TLS handshake failure messages in cache.log. I think
> the access.log messages I posted earlier are fake CONNECT requests
> created using TCP-level info (the response time logged there is
> directly proportionate to what I see in Chrome's dev tools). Guessing
> that Squid would send TCP SYN-ACK only after it receives SYN-ACK from
> remote/origin server.

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.

The first fake-CONNECT is done after TCP connection setup to see whether the client is allowed to perform TLS inside it - and how Squid handles that TLS.


> I don’t think ICAP(reqmod) would come into the picture yet either
> (assuming that even the TCP connections have not been set up yet) so
> that is safe to rule out. Am I right here ?

You are right about that in relation to TCP.

But TCP is already over and done with by the time the fake-CONNECT gets generated. So wrong about ICAP's lack of involvement - it may (or not) be.

NP: The only thing fake about the early CONNECT's is that the client did not actually generate it. They are handled in Squid same as a regular CONNECT message would be.

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid returns NONE_ABORTED/000 and high response time but the internet access itself looks okay

Amos Jeffries
Administrator
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
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: 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 <[hidden email]>
Sent: Tuesday, August 7, 2018 11:14 PM
To: Ahmad, Sarfaraz <[hidden email]>; [hidden email]
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
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users