Discussion:
[Dnsmasq-discuss] Some dns entries are not cached properly
Comerma Pare, Antoni
2016-02-03 10:47:49 UTC
Permalink
Hi,

We are experiencing some weird behavior when using dnsmasq as dns cache. We are using it in a webserver that makes lots of dns request for just a bunch of backend servers, so the # of cache entries is usually very low, but for some of these entries, dnsmasq is forwarding more requests than expected.

Here there is an extract of the requests answered by dnsmasq

awk -f dns.awk /tmp/dnsmasq.log
name | nb | forwarded | answered with cache
1m.pub.dtvc.local | 296 | 146 | 150
config.pub.dtvc.local | 434 | 197 | 242
web01.pub.dtvc.local | 10 | 5 | 5
24h.pub.dtvc.local | 12 | 6 | 6
lbfront-static.pub.dtvc.local | 31 | 6 | 25
lbfront-php-old.pub.dtvc.local | 648 | 17 | 631
memc01.pub.dtvc.local | 62286 | 28 | 62258
30m.pub.dtvc.local | 13784 | 2096 | 11694
10m.pub.dtvc.local | 17702 | 2312 | 15406
10s.pub.dtvc.local | 6522 | 2461 | 4067

DNS TTL is 3600 for all entries
10s.pub.dtvc.local, 10m.pub.dtvc.local, 30m, 24h have a low cache hit ratio (much more than expected) , while memc01.pub.dtvc.local has a high hit ratio (as expected)
The problematic entries are CNAMES, A records work as expected
The apache webserver is making requests for A and AAAA addresses. The DNS server returns NODATA-IPV6 for AAAA requests

An extract from the logfile, for 10s.pub.dtvc.local shows a lot of requests for A and AAAA. It seems than a great part of A requests are forwarded, while AAAA records are mainly cached.

This is for entry 10s.pub.dtvc.local
Feb 3 10:32:23 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:23 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1
Feb 3 10:32:23 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:23 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:23 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:25 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:25 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:25 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:25 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:27 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:27 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1
Feb 3 10:32:27 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:27 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:27 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:27 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:27 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:27 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:27 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:30 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:30 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1
Feb 3 10:32:30 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:30 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:30 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:37 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:37 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1
Feb 3 10:32:37 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME>
Feb 3 10:32:37 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:37 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME>

This is for 10m.pub.dtvc.local
Feb 3 09:57:06 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:06 dnsmasq[58096]: forwarded 10m.pub.dtvc.local to 172.20.1.1
Feb 3 09:57:06 dnsmasq[58096]: reply 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:06 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:06 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:06 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:06 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:06 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:06 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:07 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:07 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:07 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:07 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: forwarded 10m.pub.dtvc.local to 172.20.1.1
Feb 3 09:57:09 dnsmasq[58096]: reply 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: forwarded 10m.pub.dtvc.local to 172.20.1.1
Feb 3 09:57:09 dnsmasq[58096]: reply 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:09 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:10 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:10 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>
Feb 3 09:57:10 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1
Feb 3 09:57:10 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME>

Dumping the cache contents, it shows

Feb 3 09:51:28 dnsmasq[58096]: cache size 1000, 0/6659 cache insertions re-used unexpired cache entries.
Feb 3 09:51:28 dnsmasq[58096]: queries forwarded 3359, queries answered locally 71834
Feb 3 09:51:28 dnsmasq[58096]: server 172.20.1.1#53: queries sent 3359, retried or failed 2
Feb 3 09:51:28 dnsmasq[58096]: Host Address Flags Expires
Feb 3 09:51:28 dnsmasq[58096]: backend.pub.dtvc.local CF Wed Feb 3 10:00:58 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-static.pub.dtvc.local 10.111.0.23 4F Wed Feb 3 10:24:42 2016
Feb 3 09:51:28 dnsmasq[58096]: big.dtvc.local big06.dtvc.local CF Wed Feb 3 10:07:17 2016
Feb 3 09:51:28 dnsmasq[58096]: 10m.pub.dtvc.local CF Wed Feb 3 10:47:07 2016
Feb 3 09:51:28 dnsmasq[58096]: 1m.pub.dtvc.local CF Wed Feb 3 10:03:46 2016
Feb 3 09:51:28 dnsmasq[58096]: 24h.pub.dtvc.local CF Wed Feb 3 10:21:52 2016
Feb 3 09:51:28 dnsmasq[58096]: memc02.pub.dtvc.local 6F N Wed Feb 3 10:00:38 2016
Feb 3 09:51:28 dnsmasq[58096]: memc02.pub.dtvc.local 10.111.0.12 4F Wed Feb 3 10:00:38 2016
Feb 3 09:51:28 dnsmasq[58096]: memc01.pub.dtvc.local 6F N Wed Feb 3 10:00:38 2016
Feb 3 09:51:28 dnsmasq[58096]: memc01.pub.dtvc.local 10.111.0.11 4F Wed Feb 3 10:00:38 2016
Feb 3 09:51:28 dnsmasq[58096]: 172.29.120.101 4 R NX Wed Feb 3 10:35:26 2016
Feb 3 09:51:28 dnsmasq[58096]: 172.26.60.50 4 R NX Wed Feb 3 10:30:01 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-php-old.pub.dtvc.local 6F N Wed Feb 3 10:05:24 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-php-old.pub.dtvc.local 193.104.51.29 4F Wed Feb 3 09:52:01 2016
Feb 3 09:51:28 dnsmasq[58096]: lbback.pub.dtvc.local 10.111.0.26 4F Wed Feb 3 10:10:55 2016
Feb 3 09:51:28 dnsmasq[58096]: lbback.pub.dtvc.local 6F N Wed Feb 3 10:00:39 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-web-old.pub.dtvc.local 6F N Wed Feb 3 10:00:40 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-web-old.pub.dtvc.local 10.111.0.36 4F Wed Feb 3 10:00:40 2016
Feb 3 09:51:28 dnsmasq[58096]: config.pub.dtvc.local CF Wed Feb 3 10:00:44 2016
Feb 3 09:51:28 dnsmasq[58096]: big06.dtvc.local 6F N Wed Feb 3 09:48:34 2016
Feb 3 09:51:28 dnsmasq[58096]: big06.dtvc.local 172.26.11.141 4F Wed Feb 3 10:07:16 2016
Feb 3 09:51:28 dnsmasq[58096]: 30m.pub.dtvc.local lbback.pub.dtvc.local CF Wed Feb 3 10:00:37 2016

I've noticed that:

· One of the problemàtic entries, 10s.pub.dtvc.local does not appear

· 10m.pub.dtvc.local does not have "Address"

· 30m.pub.dtvc.local in contrast, has "address"= lbback.pub.dtvc.local. In fact, all 3 entries are CNAMES pointing to lbback.pub.dtvc.local

These are the symptoms, but we don't have explanation. We've digged into the man page, the lists, google, and no clues.
Toni Comerma
SECA Infraestructures i Comunicacions
c/ de la TV3 s/n · 08970 Sant Joan Despí (Baix Llobregat)
Telèfon: +34 935.522.328
Mòbil: +34 627.481.650
www.tv3.cat<http://www.tv3.cat/>
Simon Kelley
2016-02-05 22:06:24 UTC
Permalink
Post by Comerma Pare, Antoni
Hi,
We are experiencing some weird behavior when using dnsmasq as dns
cache. We are using it in a webserver that makes lots of dns
request for just a bunch of backend servers, so the # of cache
entries is usually very low, but for some of these entries, dnsmasq
is forwarding more requests than expected.
Here there is an extract of the requests answered by dnsmasq
awk -f dns.awk /tmp/dnsmasq.log name | nb | forwarded |
answered with cache 1m.pub.dtvc.local | 296 | 146 |
150 config.pub.dtvc.local | 434 | 197 | 242
web01.pub.dtvc.local | 10 | 5 | 5
24h.pub.dtvc.local | 12 | 6 | 6
lbfront-static.pub.dtvc.local | 31 | 6 |
25 lbfront-php-old.pub.dtvc.local | 648 | 17 |
631 memc01.pub.dtvc.local | 62286 | 28 | 62258
30m.pub.dtvc.local | 13784 | 2096 | 11694
10m.pub.dtvc.local | 17702 | 2312 | 15406
10s.pub.dtvc.local | 6522 | 2461 | 4067
DNS TTL is 3600 for all entries 10s.pub.dtvc.local,
10m.pub.dtvc.local, 30m, 24h have a low cache hit ratio (much more
than expected) , while memc01.pub.dtvc.local has a high hit ratio
(as expected) The problematic entries are CNAMES, A records work as
expected The apache webserver is making requests for A and AAAA
addresses. The DNS server returns NODATA-IPV6 for AAAA requests
An extract from the logfile, for 10s.pub.dtvc.local shows a lot of
requests for A and AAAA. It seems than a great part of A requests
are forwarded, while AAAA records are mainly cached.
query[A] 10s.pub.dtvc.local from 127.0.0.1 Feb 3 10:32:23
dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1 Feb 3
10:32:23 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME> Feb 3
10:32:23 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from
127.0.0.1 Feb 3 10:32:23 dnsmasq[1931]: cached 10s.pub.dtvc.local
is <CNAME> Feb 3 10:32:25 dnsmasq[1931]: query[A]
query[AAAA] 10s.pub.dtvc.local from 127.0.0.1 Feb 3 10:32:25
dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME> Feb 3 10:32:27
dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1 Feb 3
10:32:27 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to
172.26.10.1 Feb 3 10:32:27 dnsmasq[1931]: reply 10s.pub.dtvc.local
is <CNAME> Feb 3 10:32:27 dnsmasq[1931]: query[AAAA]
query[A] 10s.pub.dtvc.local from 127.0.0.1 Feb 3 10:32:27
dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME> Feb 3 10:32:27
dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from 127.0.0.1 Feb 3
10:32:27 dnsmasq[1931]: cached 10s.pub.dtvc.local is <CNAME> Feb 3
10:32:30 dnsmasq[1931]: query[A] 10s.pub.dtvc.local from 127.0.0.1
Feb 3 10:32:30 dnsmasq[1931]: forwarded 10s.pub.dtvc.local to
172.26.10.1 Feb 3 10:32:30 dnsmasq[1931]: reply 10s.pub.dtvc.local
is <CNAME> Feb 3 10:32:30 dnsmasq[1931]: query[AAAA]
query[A] 10s.pub.dtvc.local from 127.0.0.1 Feb 3 10:32:37
dnsmasq[1931]: forwarded 10s.pub.dtvc.local to 172.26.10.1 Feb 3
10:32:37 dnsmasq[1931]: reply 10s.pub.dtvc.local is <CNAME> Feb 3
10:32:37 dnsmasq[1931]: query[AAAA] 10s.pub.dtvc.local from
127.0.0.1 Feb 3 10:32:37 dnsmasq[1931]: cached 10s.pub.dtvc.local
is <CNAME>
query[A] 10m.pub.dtvc.local from 127.0.0.1 Feb 3 09:57:06
dnsmasq[58096]: forwarded 10m.pub.dtvc.local to 172.20.1.1 Feb 3
09:57:06 dnsmasq[58096]: reply 10m.pub.dtvc.local is <CNAME> Feb 3
09:57:06 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from
127.0.0.1 Feb 3 09:57:06 dnsmasq[58096]: cached 10m.pub.dtvc.local
is <CNAME> Feb 3 09:57:06 dnsmasq[58096]: query[A]
cached 10m.pub.dtvc.local is <CNAME> Feb 3 09:57:06
dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1 Feb
3 09:57:06 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME> Feb
3 09:57:07 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from
127.0.0.1 Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local
is <CNAME> Feb 3 09:57:07 dnsmasq[58096]: query[AAAA]
cached 10m.pub.dtvc.local is <CNAME> Feb 3 09:57:07
dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1 Feb 3
09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME> Feb
3 09:57:07 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from
127.0.0.1 Feb 3 09:57:07 dnsmasq[58096]: cached 10m.pub.dtvc.local
is <CNAME> Feb 3 09:57:09 dnsmasq[58096]: query[A]
forwarded 10m.pub.dtvc.local to 172.20.1.1 Feb 3 09:57:09
dnsmasq[58096]: reply 10m.pub.dtvc.local is <CNAME> Feb 3 09:57:09
dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from 127.0.0.1 Feb
3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME> Feb
3 09:57:09 dnsmasq[58096]: query[A] 10m.pub.dtvc.local from
127.0.0.1 Feb 3 09:57:09 dnsmasq[58096]: cached 10m.pub.dtvc.local
is <CNAME> Feb 3 09:57:09 dnsmasq[58096]: query[AAAA]
cached 10m.pub.dtvc.local is <CNAME> Feb 3 09:57:09
dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1 Feb 3
09:57:09 dnsmasq[58096]: forwarded 10m.pub.dtvc.local to
172.20.1.1 Feb 3 09:57:09 dnsmasq[58096]: reply 10m.pub.dtvc.local
is <CNAME> Feb 3 09:57:09 dnsmasq[58096]: query[AAAA]
cached 10m.pub.dtvc.local is <CNAME> Feb 3 09:57:10
dnsmasq[58096]: query[A] 10m.pub.dtvc.local from 127.0.0.1 Feb 3
09:57:10 dnsmasq[58096]: cached 10m.pub.dtvc.local is <CNAME> Feb
3 09:57:10 dnsmasq[58096]: query[AAAA] 10m.pub.dtvc.local from
127.0.0.1 Feb 3 09:57:10 dnsmasq[58096]: cached 10m.pub.dtvc.local
is <CNAME>
Dumping the cache contents, it shows
Feb 3 09:51:28 dnsmasq[58096]: cache size 1000, 0/6659 cache
insertions re-used unexpired cache entries. Feb 3 09:51:28
dnsmasq[58096]: queries forwarded 3359, queries answered locally
71834 Feb 3 09:51:28 dnsmasq[58096]: server 172.20.1.1#53: queries
sent 3359, retried or failed 2 Feb 3 09:51:28 dnsmasq[58096]: Host
Address Flags Expires Feb 3 09:51:28
dnsmasq[58096]: backend.pub.dtvc.local
lbfront-static.pub.dtvc.local 10.111.0.23
big.dtvc.local big06.dtvc.local
10m.pub.dtvc.local
1m.pub.dtvc.local
24h.pub.dtvc.local
memc02.pub.dtvc.local
memc02.pub.dtvc.local 10.111.0.12
memc01.pub.dtvc.local
memc01.pub.dtvc.local 10.111.0.11
172.29.120.101 4 R NX Wed Feb 3 10:35:26 2016
172.26.60.50 4 R NX Wed Feb 3 10:30:01 2016
Feb 3 09:51:28 dnsmasq[58096]: lbfront-php-old.pub.dtvc.local
lbfront-php-old.pub.dtvc.local 193.104.51.29
lbback.pub.dtvc.local 10.111.0.26
lbback.pub.dtvc.local
lbfront-web-old.pub.dtvc.local
lbfront-web-old.pub.dtvc.local 10.111.0.36
config.pub.dtvc.local
big06.dtvc.local
big06.dtvc.local 172.26.11.141
30m.pub.dtvc.local lbback.pub.dtvc.local
CF Wed Feb 3 10:00:37 2016
· One of the problemàtic entries, 10s.pub.dtvc.local does not appear
· 10m.pub.dtvc.local does not have "Address"
· 30m.pub.dtvc.local in contrast, has "address"=
lbback.pub.dtvc.local. In fact, all 3 entries are CNAMES pointing
to lbback.pub.dtvc.local
These are the symptoms, but we don't have explanation. We've digged
into the man page, the lists, google, and no clues. Toni Comerma
SECA Infraestructures i Comunicacions c/ de la TV3 s/n · 08970 Sant
Joan Despí (Baix Llobregat) Telèfon: +34 935.522.328 Mòbil: +34
627.481.650 www.tv3.cat<http://www.tv3.cat/>
The simplest explanation for this is that 10m.pub.dtvc.local is a
CNAME which points to a non-existant domain. If that was the case,
then the cache entry would last only as long as the domain's negative
TTL, which could be much shorter.


What answer do you get when you run


dig 10m.pub.dtvc.local

Cheers,

Simon.

Loading...