Re: [squid-users] mysterious TCP_DENIED messages in log

From: Amos Jeffries <squid3_at_treenet.co.nz>
Date: Sun, 03 Mar 2013 00:37:50 +1300

On 1/03/2013 5:15 a.m., equinox_at_atw.hu wrote:
> On 2/28/2013 1:19 AM, Amos Jeffries wrote:
>> On 28/02/2013 7:53 a.m., equinox_at_atw.hu wrote:
>>>
>>> Hi,
>>>
>>>
>>> Look at this log snippet.
>>>
>>> Can you see that TCP_DENIED/403 is immediately followed by
>>> TCP_REDIRECT?
>>>
>>> Is that not illogical?
>>
>> No. You cannot tell from this log what relationship any two log lines
>> may have.
>>
>> * HTTP is stateless
>> * the log indicates only the order HTTP transactions were completed.
>> * you are cropping the query-string off URLs, any two
>> seeming-identical log lines MAY be for extremely different resources
>>
>>
>>>
>>> Can you explain it? Why are there TCP_DENIED messages?
>>>
>>
>> Your config DENIED the transaction. Without details of your config
>> and the full URLs it is impossible to say more.
>>
>>
>> Amos
>>
> The urls are the same.
> I retested it. It was a test. There is not much traffic.
>
> Marton
>
>
> #
> # Recommended minimum configuration:
> #
>
> # ziproxy stuff...
> # "Hooks" Squid to Ziproxy LINK running in 'localhost', port '8081'.
> # Note: Ziproxy does not support ICP nor cache querying
> # since it is not a caching proxy.
> # cache_peer 31.222.160.30 parent 8081 0 no-query no-digest
> #debug_options ALL,9
> debug_options ALL,1 33,2 28,9 82,9
>
> #url_rewrite_program /usr/local/squid/lib/status.pl
>
> visible_hostname gb01ds
>
> cache deny all
>
> #acl manager proto cache_object
> #acl localhost src 127.0.0.1/32 ::1
> #acl to_localhost dst 127.0.0.0/8 0.0.0.0/32 ::1
>
>
> #external_acl_type myAclType ttl=10 %SRC %MYPORT %>{User-Agent}
> %{Host} /usr/local/squid/lib/authuser.pl
> external_acl_type myAclType ttl=1 %SRC %MYPORT %>{User-Agent} %{Host}
> %URI /usr/local/squid/lib/authuser2.pl
>
> acl MyAcl external myAclType
> acl comp1 tag comp1
> acl comp2 tag comp2
> acl comp3 tag comp3
> acl comp4 tag comp4
> acl comp5 tag comp5
> acl comp6 tag comp6
> acl comp7 tag comp7
> acl comp8 tag comp8
> acl comp9 tag comp9
> acl comp10 tag comp10
> acl comp11 tag comp11
> acl comp12 tag comp12
> acl comp13 tag comp13
> acl comp14 tag comp14
> acl comp15 tag comp15
> acl comp16 tag comp16
> acl comp17 tag comp17
> acl comp18 tag comp18
> acl comp19 tag comp19
> acl comp20 tag comp20
> acl comp21 tag comp21
> acl comp22 tag comp22
> acl comp23 tag comp23
> acl comp24 tag comp24
>
> acl status tag status
>
> #acl standardComp tag standard myAclType

Notice how there is no use of myTag ACL above these allow lines.
What that means is that each and every brand new request is *first*
tested to see if their brand spanking new HTTP request state contains
one of a bunch of custom tags....

> http_access allow comp1
> http_access allow comp2
> http_access allow comp3
> http_access allow comp4
> http_access allow comp5
> http_access allow comp6
> http_access allow comp7
> http_access allow comp8
> http_access allow comp9
> http_access allow comp10
> http_access allow comp11
> http_access allow comp12
> http_access allow comp13
> http_access allow comp14
> http_access allow comp15
> http_access allow comp16
> http_access allow comp17
> http_access allow comp18
> http_access allow comp19
> http_access allow comp20
> http_access allow comp21
> http_access allow comp22
> http_access allow comp23
> http_access allow comp24
>
> http_access allow status
>

*Then* only after the bunch of uselsss tag checks have been finished.
Is the myTag ACL tested which generates tags in the HTTP request state data.

All of the above https_access lines will never do anything.

> http_access allow MyAcl
>
> http_access allow all
>
> cache_peer 127.0.0.1 parent 3000 0 no-query no-digest login=PASS
> name=compServer1
> cache_peer 127.0.0.1 parent 3001 0 no-query no-digest login=PASS
> name=compServer2
> cache_peer 127.0.0.1 parent 3002 0 no-query no-digest login=PASS
> name=compServer3
> cache_peer 127.0.0.1 parent 3003 0 no-query no-digest login=PASS
> name=compServer4
> cache_peer 127.0.0.1 parent 3004 0 no-query no-digest login=PASS
> name=compServer5
> cache_peer 127.0.0.1 parent 3005 0 no-query no-digest login=PASS
> name=compServer6
> cache_peer 127.0.0.1 parent 3006 0 no-query no-digest login=PASS
> name=compServer7
> cache_peer 127.0.0.1 parent 3007 0 no-query no-digest login=PASS
> name=compServer8
> cache_peer 127.0.0.1 parent 3008 0 no-query no-digest login=PASS
> name=compServer9
> cache_peer 127.0.0.1 parent 3009 0 no-query no-digest login=PASS
> name=compServer10
> cache_peer 127.0.0.1 parent 3010 0 no-query no-digest login=PASS
> name=compServer11
> cache_peer 127.0.0.1 parent 3011 0 no-query no-digest login=PASS
> name=compServer12
> cache_peer 127.0.0.1 parent 3012 0 no-query no-digest login=PASS
> name=compServer13
> cache_peer 127.0.0.1 parent 3013 0 no-query no-digest login=PASS
> name=compServer14
> cache_peer 127.0.0.1 parent 3014 0 no-query no-digest login=PASS
> name=compServer15
> cache_peer 127.0.0.1 parent 3015 0 no-query no-digest login=PASS
> name=compServer16
> cache_peer 127.0.0.1 parent 3016 0 no-query no-digest login=PASS
> name=compServer17
> cache_peer 127.0.0.1 parent 3017 0 no-query no-digest login=PASS
> name=compServer18
> cache_peer 127.0.0.1 parent 3018 0 no-query no-digest login=PASS
> name=compServer19
> cache_peer 127.0.0.1 parent 3019 0 no-query no-digest login=PASS
> name=compServer20
> cache_peer 127.0.0.1 parent 3020 0 no-query no-digest login=PASS
> name=compServer21
> cache_peer 127.0.0.1 parent 3021 0 no-query no-digest login=PASS
> name=compServer22
> cache_peer 127.0.0.1 parent 3022 0 no-query no-digest login=PASS
> name=compServer23
> cache_peer 127.0.0.1 parent 3023 0 no-query no-digest login=PASS
> name=compServer24
>
> cache_peer_access compServer1 allow comp1
> cache_peer_access compServer1 deny !comp1
> cache_peer_access compServer2 allow comp2
> cache_peer_access compServer2 deny !comp2
> cache_peer_access compServer3 allow comp3
> cache_peer_access compServer3 deny !comp3
> cache_peer_access compServer4 allow comp4
> cache_peer_access compServer4 deny !comp4
> cache_peer_access compServer5 allow comp5
> cache_peer_access compServer5 deny !comp5
> cache_peer_access compServer6 allow comp6
> cache_peer_access compServer6 deny !comp6
> cache_peer_access compServer7 allow comp7
> cache_peer_access compServer7 deny !comp7
> cache_peer_access compServer8 allow comp8
> cache_peer_access compServer8 allow status
>
> cache_peer_access compServer8 deny !comp8
>
> cache_peer_access compServer9 allow comp9
> cache_peer_access compServer9 deny !comp9
> cache_peer_access compServer10 allow comp10
> cache_peer_access compServer10 deny !comp10
> cache_peer_access compServer11 allow comp11
> cache_peer_access compServer11 deny !comp11
> cache_peer_access compServer12 allow comp12
> cache_peer_access compServer12 deny !comp12
> cache_peer_access compServer13 allow comp13
> cache_peer_access compServer13 deny !comp13
> cache_peer_access compServer14 allow comp14
> cache_peer_access compServer14 deny !comp14
> cache_peer_access compServer15 allow comp15
> cache_peer_access compServer15 deny !comp15
> cache_peer_access compServer16 allow comp16
> cache_peer_access compServer16 deny !comp16
> cache_peer_access compServer17 allow comp17
> cache_peer_access compServer17 deny !comp17
> cache_peer_access compServer18 allow comp18
> cache_peer_access compServer18 deny !comp18
> cache_peer_access compServer19 allow comp19
> cache_peer_access compServer19 deny !comp19
> cache_peer_access compServer20 allow comp20
> cache_peer_access compServer20 deny !comp20
> cache_peer_access compServer21 allow comp21
> cache_peer_access compServer21 deny !comp21
> cache_peer_access compServer22 allow comp22
> cache_peer_access compServer22 deny !comp22
> cache_peer_access compServer23 allow comp23
> cache_peer_access compServer23 deny !comp23
> cache_peer_access compServer24 allow comp24
> cache_peer_access compServer24 deny !comp24
>
> #url_rewrite_access allow status
> #url_rewrite_access all
> #url_rewrite_access deny all
>
> #cache_peer_access vlowServer allow v
> #cache_peer_access vlowServer deny all
>
> #acl ncsa_users proxy_auth REQUIRED
> #http_access allow ncsa_users
> #acl ncsa max_user_ip 999
>
>
> # Example rule allowing access from your local networks.
> # Adapt to list your (internal) IP networks from where browsing
> # should be allowed
> acl localnet src 127.0.0.0/8 # RFC1918 possible internal network
> #acl localnet src 172.16.0.0/12 # RFC1918 possible internal network
> #acl localnet src 192.168.0.0/16 # RFC1918 possible internal network
> #acl localnet src fc00::/7 # RFC 4193 local private network range
> #acl localnet src fe80::/10 # RFC 4291 link-local (directly
> plugged) machines
>

Er.. local*net* ACL is the LAN or local network IP address ranges. Are
you sure this is right?

PS. there is a built-in ACL named "localhost" (note the 'host' piece)
which matched 127.0.0.0/8 and ::1/128 for when you need to match
machine-internal traffic on the lo interface.

> acl SSL_ports port 443 563
> acl Safe_ports port 80 # http
> acl Safe_ports port 21 # ftp
> acl Safe_ports port 443 # https
> acl Safe_ports port 70 # gopher
> acl Safe_ports port 210 # wais
> acl Safe_ports port 1025-65535 # unregistered ports
> acl Safe_ports port 280 # http-mgmt
> acl Safe_ports port 488 # gss-http
> acl Safe_ports port 591 # filemaker
> acl Safe_ports port 777 # multiling http
>
> acl CONNECT method CONNECT
>
> #
> # Recommended minimum Access Permission configuration:
> #
> # Only allow cachemgr access from localhost
> #http_access allow manager localhost
> #http_access deny manager
>
> # Deny requests to certain unsafe ports
> http_access deny !Safe_ports
>
> # Deny CONNECT to other than secure SSL ports
> http_access deny CONNECT !SSL_ports
>
> # We strongly recommend the following be uncommented to protect innocent
> # web applications running on the proxy server who think the only
> # one who can access services on "localhost" is a local user
> #http_access deny to_localhost
>
> #
> # INSERT YOUR OWN RULE(S) HERE TO ALLOW ACCESS FROM YOUR CLIENTS
> #
>
> # Example rule allowing access from your local networks.
> # Adapt localnet in the ACL section to list your (internal) IP networks
> # from where browsing should be allowed
> #http_access allow localnet
> #http_access allow localhost
>
> # And finally deny all other access to this proxy
> http_access deny all
>
>
> # We recommend you to use at least the following line.
> hierarchy_stoplist cgi-bin ?
>

The hierarchy_stoplist directive is not useful any longer. You can drop
it from your config.

> # Uncomment and adjust the following to add a disk cache directory.
> #cache_dir ufs /usr/local/squid/var/cache 100 16 256
>
> # Leave coredumps in the first cache dir
> #coredump_dir /usr/local/squid/var/cache
>
> # Add any of your own refresh_pattern entries above these.
> refresh_pattern ^ftp: 1440 20% 10080
> refresh_pattern ^gopher: 1440 0% 1440
> refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
> refresh_pattern . 0 20% 4320
>
>
> # extras...
>
> logformat Squid %{%Y-%m-%dT%H:%M:%S}tg.%03tu %ts.%03tu %6tr %>A
> %Ss/%03Hs %<st %rm %ru %rp %un %Sh %et
> #access_log /var/log/squid/access.log Squid
> #cache_log /var/log/squid/cache.log Squid

You do not need to define the Squid native logformat in your config
file. It is built-in nowdays. If you have altered anything please change
the format name to avoid confusion.

PS. Notice that the documented format for the native logformat is for
documentation purposes only in describing the format fields. The real
native format does not have the same -/nil behaviour in some fields as
the custom field codes do.

>
> # Prevents Squid trying to access directly the remote HTTP host
> # if Squid is unable to connect to Ziproxy,
> # otherwise you won't know whether Ziproxy is down/has_problems
> # (the lack of gzip support is not obvious to the user).
> #never_direct allow all
> always_direct allow all

Quite a kicker. So all of that cache_peer configuration is useless? all
traffic is to ALWAYS go DIRECTly to the servers found in DNS, without
going to any cache_peer.

Choose one:
  - remove always_direct allow all
  - remove every line in squid.conf starting with cache_peer...

Otherwise Squid will do the choosing for you.

> url_rewrite_program /root/videocomp/videorewriter.pl
>
> # Squid normally listens to port 3128
> #include /usr/local/squid/etc/squid_ports.conf
> include /usr/local/squid/etc/squid_ports_1.conf

The content of that extra configuration file is also needed.

> pid_filename /usr/local/squid/var/run/squid_1.pid
> access_log /var/log/squid/access_1.log Squid
> cache_log /var/log/squid/cache_1.log Squid
>

You cannot determine the format of the cache.log. It is the debug and
administrative messages log for Squid.

So you ave either configured garbage in squid.conf or configured Squid
to log to a file called "/var/log/squid/cache_1.log Squid"

>
> An example of denial:
> 013/02/28 12:10:04.232 kid1| external_acl.cc(1389) ExternalAclLookup:
> externalAclLookup: lookup in 'myAclType' for '95.215.120.184 3257
> AppleCoreMedia/1.0.0.10B146%20(iPhone;%20U;%20CPU%20OS%206_1_2%20like%20Mac%20OS%20X;%20en_us)
> 5.79.$
> 2013/02/28 12:10:04.232 kid1| external_acl.cc(1459) ExternalAclLookup:
> externalAclLookup: looking up for '95.215.120.184 3257
> AppleCoreMedia/1.0.0.10B146%20(iPhone;%20U;%20CPU%20OS%206_1_2%20like%20Mac%20OS%20X;%20en_us)
> 5.79.6.204 http:$
> 2013/02/28 12:10:04.233 kid1| external_acl.cc(1471) ExternalAclLookup:
> externalAclLookup: no need to wait for the result of '95.215.120.184
> 3257
> AppleCoreMedia/1.0.0.10B146%20(iPhone;%20U;%20CPU%20OS%206_1_2%20like%20Mac%20OS%20X;%20en_u$
> 2013/02/28 12:10:04.233 kid1| external_acl.cc(1472) ExternalAclLookup:
> externalAclLookup: using cached entry 0x2a12cd8
> 2013/02/28 12:10:04.233 kid1| external_acl.cc(1479) ExternalAclLookup:
> externalAclLookup: entry = { date=1362053403, result=1 tag=comp3 log= }
> 2013/02/28 12:10:04.233 kid1| external_acl.cc(1481) ExternalAclLookup:
> externalAclLookup: user=3257|0|3|8
> 2013/02/28 12:10:04.233 kid1| Checklist.cc(141) asyncInProgress:
> ACLChecklist::asyncInProgress: 0x27da918 async set to 0
> 2013/02/28 12:10:04.233 kid1| Checklist.cc(229) matchAclList:
> aclmatchAclList: async=1 nodeMatched=0 async_in_progress=0
> lastACLResult() = 0 finished() = 0
> 2013/02/28 12:10:04.233 kid1| Checklist.cc(243) matchAclList:
> aclmatchAclList: 0x27da918 returning (AND list entry awaiting an async
> lookup)

Hmm. I notice that the external ACL found a cached OK result but sent
fail result back to the ACL checker. Which made it continue on to the
"http_access deny all" line later in the config.

Amos
Received on Sat Mar 02 2013 - 11:38:12 MST

This archive was generated by hypermail 2.2.0 : Tue Mar 05 2013 - 12:00:03 MST