[Dnsmasq-discuss] Slow resolving

[Lars Noodén]

> It's likely to be a problem with one or more of the upstream
> servers. I suggest setting the dnsmasq "log-queries" option
> and then examining what servers the slow query was sent to,
> and how long they took to reply, or of they didn't reply at all.

Thanks, Simon.  Adding "log-queries" and then polling with SIGUSR1 gives
me some information but not the query time.  Here is the output from
that.  How would I get the timing information as well?

[snip]
 dnsmasq: query[A] en.wikibooks.org from 192.168.1.12

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.aa

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.bb

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.cc

 dnsmasq: query[AAAA] en.wikibooks.org from 192.168.1.12

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.aa

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.bb

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.cc

 dnsmasq: query[MX] en.wikibooks.org from 192.168.1.12

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.aa

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.bb

 dnsmasq: forwarded en.wikibooks.org to xx.yy.zz.cc

 dnsmasq: time 1525965956
 dnsmasq: cache size 150, 0/0 cache insertions re-used unexpired cache
entries.
 dnsmasq: queries forwarded 21, queries answered locally 3

 dnsmasq: queries for authoritative zones 0

 dnsmasq: server xx.yy.zz.aa#53: queries sent 21, retried or failed 0

 dnsmasq: server xx.yy.zz.bb#53: queries sent 21, retried or failed 0

 dnsmasq: server xx.yy.zz.cc#53: queries sent 21, retried or failed 0

[snip]

If I remove the dnsmasq machine from /etc/resolv.conf, the queries
become fast again, so there is somehow a delay on my end.

Can it be that the ISP's DNS servers are imposing a 5-second delay for
these queries?

Here is what I've tried to get with tcpdump on the router for one query:

[snip]
18:51:28.604361 IP 192.168.1.12.53259 > 192.168.1.1.53: UDP, length 37
E..A:. at .@...
.       "
.       ....5.-&w.............www.raspberrypi.org.....
18:51:28.604383 IP 192.168.1.12.53259 > 192.168.1.1.53: UDP, length 37
E..A:. at .@...
.       "
.       ....5.-&w.l...........www.raspberrypi.org.....
18:51:33.608889 IP 192.168.1.12.50138 > xx.yy.zz.aa.53: UDP, length 37
E..AZD at .@..U
.       ".......5.-.P.............www.raspberrypi.org.....
18:51:33.608988 IP 192.168.1.12.50138 > xx.yy.zz.aa.53: UDP, length 37
E..AZE at .@..T
.       ".......5.-.P.l...........www.raspberrypi.org.....
18:51:33.625188 IP xx.yy.zz.aa.53 > 192.168.1.12.50138: UDP, length 182
E...LN at ...M.....
.       ".5.............
.....www.raspberrypi.org..................lb...1.......\..]]...1.......\..]]...1.......\..]]...1.......\..]]...1.......\..]]...1.......\..]].'.1.......\..]].h.1.......\......
18:51:33.625926 IP xx.yy.zz.aa.53 > 192.168.1.12.50138: UDP, length 278
E..2Lk at ...M=....
.       ".5.......l.....
.....www.raspberrypi.org..................lb...1..........*................1..........*................1..........*................1..........*................1..........*..............

.1..........*................1..........*................1..........*...............
18:51:34.031898 IP 192.168.1.12.36202 > 192.168.1.1.53: UDP, length 37
E..A?. at .@...
.       "
.       ..j.5.-&w.............www.raspberrypi.org.....
18:51:34.031915 IP 192.168.1.12.36202 > 192.168.1.1.53: UDP, length 37
E..A?. at .@...
.       "
.       ..j.5.-&w.............www.raspberrypi.org.....
18:51:34.032247 IP 192.168.1.12.47119 > 192.168.1.1.53: UDP, length 37
E..A?. at .@...
.       "
.       ....5.-&w. at ...........www.raspberrypi.org.....
[snip]

Thanks,
Lars