Re: [squid-users] TCP_MISS then TCP_DENIED

On 30/07/2014 5:18 a.m., peter_at_pshankland.co.uk wrote:
> Hi, I have configured a new install of Squid on CentOS 6.5 via yum. I
> have followed some of the guides on the Squid wiki to get AD group
> authentication working but am getting some strange results when looking
> within the access.log.
>
> As you can see from the following log entries, the server, with an
> authentication user logged in and browsing to www.google.com, gets a
> couple of TCP_MISS/200 entries and then TCP_DENIED/407 before going back
> to TCP_MISS/200 again:
>
> 1406653633.180 220 172.29.94.15 TCP_MISS/200 3863 CONNECT
> ssl.gstatic.com:443 admin_pete DIRECT/74.125.230.119 -
> 1406653633.180 78 172.29.94.15 TCP_MISS/200 3524 CONNECT
> www.google.com:443 admin_pete DIRECT/173.194.41.116 -
> 1406653633.182 0 172.29.94.15 TCP_DENIED/407 3951 CONNECT
> www.google.com:443 - NONE/- text/html
> 1406653633.185 0 172.29.94.15 TCP_DENIED/407 4280 CONNECT
> www.google.com:443 - NONE/- text/html
> 1406653633.194 0 172.29.94.15 TCP_DENIED/407 3955 CONNECT
> ssl.gstatic.com:443 - NONE/- text/html
> 1406653633.196 0 172.29.94.15 TCP_DENIED/407 4284 CONNECT
> ssl.gstatic.com:443 - NONE/- text/html
> 1406653633.247 72 172.29.94.15 TCP_MISS/200 3862 CONNECT
> www.gstatic.com:443 admin_pete DIRECT/74.125.230.127 -
> 1406653633.249 0 172.29.94.15 TCP_DENIED/407 3955 CONNECT
> www.gstatic.com:443 - NONE/- text/html
> 1406653633.252 0 172.29.94.15 TCP_DENIED/407 4284 CONNECT
> www.gstatic.com:443 - NONE/- text/html
> 1406653633.394 0 172.29.94.15 TCP_DENIED/407 3955 CONNECT
> apis.google.com:443 - NONE/- text/html
>
> It is a bit confusing as the web page loads but I get all these denied
> logs within access.log.
>
> Could someone help me understand what this means?

Since you mention "AD group authentication" I asume you have used NTLM
or Negotiate authentication.

Two things to be aware of when reading these logs:

1) the entries are logged at time of transaction completion. So the
admin_pete CONNECT requests that got a MISS/200 actually started far
earlier than the denied ones. eg the one 1406653633 (logged) - 72ms
(duration) ==> started 1406653561.

 ... that helps you read the log for identifying #2 ...

2) Authentication requires multiple HTTP transactions to perform an
authentication handshake. Both NTLM and Negotiate have mandatory fresh
handshakes on every new connection. NTLM always has an extra transaction
in the middle of the handshake.
So you get a denied first then a success. This shows up worst of all
with HTTPS like above where every tunnnel attempt requires a new connection.

3) browsers also have a tendency to open multiple connections at a time.
Sometimes this can be attributed to "happy eyeballs" sometimes they are
just grabbing more for future performance. That (or NTLM) is probably
the case for these attempts which are only 3ms apart.

Amos
Received on Wed Jul 30 2014 - 04:39:16 MDT