[squid-users] Possible access via v6 when no interfaces present, fixable with dns_v4_first

Sat May 19 02:14:34 UTC 2018

Hello squid users,

I'm trying to understand a strange problem with requests to edge.apple.com,
which I think may be related to IPv6 DNS resolution.

To set the scene - we operate a large (1,000+) fleet of Squid 3.5.25 caches.
Each runs on a separate LAN, connected to the internet via another upstream
proxy, accessed over a wide-area network.  Each local cache runs on a CentOS
6 box, incuding BIND for name resolution.  For DNS resolution, each local
CentOS server runs BIND, which is configured to resolve against a local
Microsoft DNS server, which then resolves internet queries using a
whole-of-WAN BIND service operated by the carrier.  The WAN does not support
IPv6, and CentOS does not have any v6 network interfaces configured.

Recently we became aware of a fault on a single cache serving requests for
edge.icloud.com.  Requests would time out with a TAG_NONE/503 written to the
log.  The error could be replicated with cURL at the CLI using this URL:
https://edge.icloud.com/perf.css.  This was a strange error, because at the
time it happened, it was possible to connect to edge.icloud.com on port 443.
The error was happening in just one site.

To isolate the fault we stripped the Squid config at the affected site right
back to the following:

	# Skeleton Squid 3.5.25 config
	shutdown_lifetime 2 seconds
	max_filedesc 16384
	coredump_dir /var/spool/squid
	dns_timeout 5 seconds
	error_directory /var/www/squid-errors
	logfile_rotate 0
	http_port 3128
	cache_dir ufs /var/spool/squid 8192 16 256
	maximum_object_size 536870912 bytes
	cache_replacement_policy heap LFUDA
	http_access allow localhost
	debug_options ALL,5

Here's the messages written to the log when fetching
https://edge.icloud.com/perf.css with curl:

2018/05/08 16:25:46.321 kid1| 14,3| ipcache.cc(362) ipcacheParse: 18 answers
for 'edge.icloud.com'
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #0 [2403:300:a50:105::f]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #1 [2403:300:a50:105::9]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #2 [2403:300:a50:100::e]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #3 [2403:300:a50:101::5]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #4 [2403:300:a50:104::e]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #5 [2403:300:a50:104::9]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #6 [2403:300:a50:104::5]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(431) ipcacheParse:
edge.icloud.com #7 [2403:300:a50:101::6]
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #8 17.248.155.107
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #9 17.248.155.142
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #10 17.248.155.110
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #11 17.248.155.80
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #12 17.248.155.114
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #13 17.248.155.77
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #14 17.248.155.145
2018/05/08 16:25:46.322 kid1| 14,3| ipcache.cc(420) ipcacheParse:
edge.icloud.com #15 17.248.155.89
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(280) peerSelectDnsPaths:
Found sources for 'edge.icloud.com:443'
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(281) peerSelectDnsPaths:
always_direct = DENIED
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(282) peerSelectDnsPaths:
never_direct = DENIED
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:105::f]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:105::9]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:100::e]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:101::5]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:104::e]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:104::9]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:104::5]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=[::] remote=[2403:300:a50:101::6]:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.107:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.142:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.110:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.80:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.114:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.77:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.145:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths:
DIRECT = local=0.0.0.0 remote=17.248.155.89:443 flags=1
2018/05/08 16:25:46.322 kid1| 44,2| peer_select.cc(295) peerSelectDnsPaths:
timedout = 0

After adding "dns_v4_first on" to the config, this allowed the request to
proceed.  Great!

We're interested to know why this copy of Squid acted differently to all the
others.  One potential clue we noticed is that this particular LAN has a lot
of v6 trafflic flying around on it, compared to the rest of our networks.  I
understand Squid runs it's own DNS resolver.  Could something on the local
LAN be announcing itself and the resolver in Squid picking up on that,
switching around the order of DNS resolution so that it tries that v6
address first?

Anything else we should be looking for?  Guidance appreciated!

Cheers
Luke