[squid-users] acl matching not working correctly

I have been chasing down problems with squid ever since I updated to
v3.3.2. I have found one that looks a lot like a bug with the acl
matching. I have a particular IP address that people here are trying to
access that we cannot access because a cache peer is not selected. I
use cache_peer_access to perform some routing of requests but I have
found in the instance of this particular IP address (not all IP
addresses) that if there are any deny statements in the
cache_peer_access then squid is behaving as though the ACL is matched
even though there is no way it could ever match. I have stripped a test
config down to the barest minimum:

debug_options ALL,2
logfile_rotate 0
cache_peer edpsvwcg001.au.baesystems.com parent 8080 0 login=*:password
default
auth_param basic program /usr/bin/ntlm_auth
--helper-protocol=squid-2.5-basic
auth_param basic children 150
auth_param basic realm BAE SYSTEMS Web Proxy Server
auth_param basic credentialsttl 2 hours
icp_port 3130
external_acl_type user_rewrite_type children-max=60 children-startup=20
ttl=900 %LOGIN /opt/local/squid/libexec/user_rewrite.pl
acl user_rewrite external user_rewrite_type
acl localnet src 10.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
acl localnet src 150.207.0.0/16
acl SSL_ports port 443
acl SSL_ports port 2096 # refer call # 510849
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
http_access allow manager localhost
http_access deny manager
acl foo dstdomain .bandersnatch.snark
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
cache_peer_access edpsvwcg001.au.baesystems.com deny foo
cache_peer_access edpsvwcg001.au.baesystems.com allow all
acl auth proxy_auth REQUIRED
http_access deny !auth
http_access allow auth user_rewrite
http_access deny all
http_port 3128
cache_dir ufs /cache1 1200 16 256
coredump_dir /cache1
logformat bae_cust %ts.%03tu %6tr %>a/%{X-Forwarded-For}>h %Ss/%03>Hs
%<st %rm %ru %un %Sh/%<A %mt %{Referer}>h "%{User-Agent}>h"
cache_log /cache1/logs/cache.log
cache_store_log none
cache_access_log /cache1/logs/access.log bae_cust
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
always_direct deny all
never_direct allow all
uri_whitespace allow
strip_query_terms off
dns_v4_first on
pid_filename /var/run/squid.pid

note the ACL foo in the config, note also the cache_peer_access.
Running with squid -k debug on I see:

2013/05/09 10:33:55.385 kid1| Starting new basicauthenticator helpers...
2013/05/09 10:33:55.385 kid1| helperOpenServers: Starting 1/150 'ntlm_auth' processes
[2013/05/09 10:33:55.408197, 1] param/loadparm.c:6516(map_parameter) Unknown parameter encountered: "use kerberos keytab"
[2013/05/09 10:33:55.408363, 0] param/loadparm.c:7610(lp_do_parameter) Ignoring unknown parameter "use kerberos keytab"
2013/05/09 10:33:55.416 kid1| User.cc(338) addIp: user 'au\blymn' has been seen at a new IP address (150.207.18.81:45941)
2013/05/09 10:33:55.416 kid1| external_acl.cc(838) aclMatchExternal: user_rewrite_type("au%5Cblymn") = lookup needed
2013/05/09 10:33:55.416 kid1| external_acl.cc(840) aclMatchExternal: "au%5Cblymn": entry=@0, age=0
2013/05/09 10:33:55.416 kid1| external_acl.cc(843) aclMatchExternal: "au%5Cblymn": queueing a call.
2013/05/09 10:33:55.416 kid1| external_acl.cc(845) aclMatchExternal: "au%5Cblymn": return -1.
2013/05/09 10:33:55.416 kid1| external_acl.cc(1407) Start: fg lookup in 'user_rewrite_type' for 'au%5Cblymn'
2013/05/09 10:33:55.416 kid1| external_acl.cc(1323) externalAclHandleReply: externalAclHandleReply: reply="OK user=blymn password=special"
2013/05/09 10:33:55.416 kid1| external_acl.cc(1232)
external_acl_cache_add: external_acl_cache_add: Adding 'au%5Cblymn' = ALLOWED
2013/05/09 10:33:55.416 kid1| external_acl.cc(875) aclMatchExternal: user_rewrite_type = ALLOWED
2013/05/09 10:33:55.416 kid1| client_side_request.cc(778) clientAccessCheckDone: The request GET ftp://XX.XX.XX.XX/ is ALLOWED, because it matched 'user_rewrite'
2013/05/09 10:33:55.416 kid1| client_side_request.cc(752) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
2013/05/09 10:33:55.416 kid1| client_side_request.cc(778) clientAccessCheckDone: The request GET ftp://XX.XX.XX.XX/ is ALLOWED, because it matched 'user_rewrite'
2013/05/09 10:33:55.416 kid1| forward.cc(121) FwdState: Forwarding client request local=150.207.4.98:3128 remote=150.207.18.81:45941 FD 9 flags=1, url=ftp://XX.XX.XX.XX/
2013/05/09 10:33:55.416 kid1| Failed to select source for 'ftp://XX.XX.XX.XX/'
2013/05/09 10:33:55.416 kid1| always_direct = DENIED
2013/05/09 10:33:55.416 kid1| never_direct = ALLOWED
2013/05/09 10:33:55.416 kid1| timedout = 0
2013/05/09 10:33:55.417 kid1| client_side_reply.cc(1974) processReplyAccessResult: The reply for GET ftp://XX.XX.XX.XX/ is ALLOWED, because it matched 'foo'
2013/05/09 10:33:55.417 kid1| client_side.cc(1386) sendStartOfMessage: HTTP Client local=150.207.4.98:3128 remote=150.207.18.81:45941 FD 9 flags=1
2013/05/09 10:33:55.417 kid1| client_side.cc(1387) sendStartOfMessage:
HTTP Client REPLY:
---------
HTTP/1.1 500 Internal Server Error
Server: squid/3.3.2
Mime-Version: 1.0
Date: Thu, 09 May 2013 01:03:55 GMT
Content-Type: text/html
Content-Length: 3833
X-Squid-Error: ERR_CANNOT_FORWARD 0
Vary: Accept-Language
Content-Language: en-us
X-Cache: MISS from edpsvrheltest002
X-Cache-Lookup: MISS from edpsvrheltest002:3128
Via: 1.1 edpsvrheltest002 (squid/3.3.2)
Connection: keep-alive

----------
2013/05/09 10:33:55.417 kid1| fqdncacheParse: No PTR record for 'XX.XX.XX.XX'
2013/05/09 10:33:55.417 kid1| fqdncacheParse: No PTR record for 'XX.XX.XX.XX'
2013/05/09 10:33:55.417 kid1| fqdncacheParse: No PTR record for 'XX.XX.XX.XX'
2013/05/09 10:33:55.417 kid1| fqdncacheParse: No PTR record for 'XX.XX.XX.XX'
2013/05/09 10:33:55.417 kid1| fqdncacheParse: No PTR record for 'XX.XX.XX.XX'

Sorry for obscuring the IP, it is a third party site and I don't know if
they want it advertised. I can supply the address if needed for
debug/testing privately. The weird thing here is the acl foo can in no
way match anything - it certainly has nothing to do with the IP address
at all but we get a reply saying the IP address matched foo and hence
the cache access is denied resulting in no parent being selected.

If I try the same with, say, ftp.netbsd.org using ftp://199.233.217.249/
then the ftp works. I am suspecting squid maybe trying to perform a
reverse lookup on the IP and getting something odd... if I do a dig -x
on the IP I get:

;; ANSWER SECTION:
XX.XX.XX.XX.in-addr.arpa. 81229 IN CNAME 3.0/XX.XX.XX.XX.in-addr.arpa.

which is strange. I can work around this by putting an allow
cache_peer_access that matches the IP prior to any deny statements but,
still, something is not right.

-- 
Brett Lymn
"Warning:
The information contained in this email and any attached files is
confidential to BAE Systems Australia. If you are not the intended
recipient, any use, disclosure or copying of this email or any
attachments is expressly prohibited.  If you have received this email
in error, please notify us immediately. VIRUS: Every care has been
taken to ensure this email and its attachments are virus free,
however, any loss or damage incurred in using this email is not the
sender's responsibility.  It is your responsibility to ensure virus
checks are completed before installing any data sent in this email to
your computer."