[Dnsmasq-discuss] Logging milliseconds

[Albert ARIBAUD]

Hi Manfred,

Le Tue, 21 Jun 2016 18:25:44 +0200
<mabra at manfbraun.de> a écrit:

> Hi !
> 
> If it comes to webbrowsing, it comes to complexity. But if I wish
> to analyze dns, I go to the commandline. If one has 30 instances
> of Firefox, you cannot control something - it is always slower,
> while for Chrome, due to its multiprocess design, it keeps fast.

See below (*)

> So I usually do not look at apps, I look to the network. I make
> direct test to dns and there is really the problem. So I present
> a little dnsmasq log here:
> 
> Q Jun 21 13:14:46 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:14:46 dnsmasq[28673]: forwarded startpage.com to 213.73.91.35
>   Jun 21 13:14:46 dnsmasq[28673]: query[A] startpage.com.mbg.local from 192.168.26.9
>   Jun 21 13:14:46 dnsmasq[28673]: config startpage.com.mbg.local is NXDOMAIN-IPv4
>   Jun 21 13:14:46 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:14:46 dnsmasq[28673]: forwarded startpage.com to 213.73.91.35
>   Jun 21 13:14:46 dnsmasq[28673]: query[A] www.manne.eu.mbg.local from 192.168.26.254
>   Jun 21 13:14:46 dnsmasq[28673]: config www.manne.eu.mbg.local is NXDOMAIN-IPv4
>   Jun 21 13:14:51 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:14:51 dnsmasq[28673]: forwarded startpage.com to 85.214.73.63
>   Jun 21 13:14:51 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:14:51 dnsmasq[28673]: forwarded startpage.com to 85.214.73.63
>   Jun 21 13:14:56 dnsmasq[28673]: query[A] startpage.com.mbg.local from 192.168.26.9
>   Jun 21 13:14:56 dnsmasq[28673]: config startpage.com.mbg.local is NXDOMAIN-IPv4
>   Jun 21 13:14:56 dnsmasq[28673]: query[A] startpage.com.mbg.local from 192.168.26.9
>   Jun 21 13:14:56 dnsmasq[28673]: config startpage.com.mbg.local is NXDOMAIN-IPv4
>   Jun 21 13:14:56 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:14:56 dnsmasq[28673]: forwarded startpage.com to 213.73.91.35
>   Jun 21 13:15:01 dnsmasq[28673]: query[A] startpage.com from 192.168.26.9
>   Jun 21 13:15:01 dnsmasq[28673]: forwarded startpage.com to 85.214.73.63
>   Jun 21 13:15:01 dnsmasq[28673]: query[A] www.manfbraun.de from 192.168.26.254
>   Jun 21 13:15:01 dnsmasq[28673]: cached www.manfbraun.de is 84.201.92.70
>   Jun 21 13:15:01 dnsmasq[28673]: query[AAAA] www.manfbraun.de from 192.168.26.254
>   Jun 21 13:15:01 dnsmasq[28673]: forwarded www.manfbraun.de to 213.73.91.35
>   Jun 21 13:15:06 dnsmasq[28673]: query[A] startpage.com.mbg.local from 192.168.26.9
>   Jun 21 13:15:06 dnsmasq[28673]: config startpage.com.mbg.local is NXDOMAIN-IPv4
>   Jun 21 13:15:06 dnsmasq[28673]: query[A] startpage.com from
> 192.168.26.9 Jun 21 13:15:06 dnsmasq[28673]: forwarded startpage.com
> to 213.73.91.35 R Jun 21 13:15:06 dnsmasq[28673]: reply startpage.com
> is 37.0.87.19
> 
> You'll easily see, that the first request to "startpage.com" [markey
> by Q] is followed by several other and even to different DNS, and the
> first reply arrives 20 seconds (!!) later [marked by R] and you'll
> not know, which DNS provided the answer.

I do indeed notice that the local machine 192.168.26.9 sends several
queries to the dnsmasq instance in the same second, and that the
answer takes 20 seconds to come back.

Re: the multiple queries, looking at the first second logged (13:14:46):

Apparently, the first three queries are for one name (startpage.com),
and the fourth one is for another (www.manne.eu). As the fourth one
seems unrelated, I'll put it aside (as I will www.manfbraun.de in the
later part of the log). This leaves three requests within one second.

AFAIU, the first two requests are sent in parallel by the client because
it thinks that "startpage.com" could be a complete global name or a
local prefix under the local net "mbg.local". I may be wrong but I see
no issue there.

Also, I see that there are bursts of queries, and within each burst,
dnsmasq queries one upstream server, and basically alternates on each
burst. There too, it does not strike me as odd.

This leaves the question of why the client asked for "startpage.com"
twice in the same second, and why it keeps asking for the same name
eight times in 20 seconds, which is way below e.g. a TCP connection
failure timeout. There is a reason why dnsmasq does not query its
upstream server several times per second for a given name (it's in the
RFC IIRC, and although I don't remember any timeout value being
specified, less than a second does not make sense).

[why it keeps asking for a name it has received a NXDOMAIN for
surprises me too -- although maybe it expects the name to suddenly
appear -- but anyway, it got its answer there immediately.]

Now, you are linking the [R] answers with the [Q] query at 14:14:46,
but it could just as well be linked with the last query at 13:15:06,
and all other requests were just not received upstream.

That, a tcpdump on the dnsmasq machine would tell us.

> Has nothing to do with other apps-delays.
> 
> A good logentry would look like this:
> 
> > Jun 21 13:15:06.987 dnsmasq[28673]:  
> reply startpage.com for client-req 192.168.26.10 (at Jun 21 13:15:05.337) is 37.0.87.19 from 213.73.91.35
> 
> [made it two lines].
> 
> I have the problem for a long time now and the provider always claims to
> fixed it - was never true. I think, they have a random genrator to make
> disturbences. I just this moment entered the IPS-DSN and everyworks well.
> Sad, that dnsmasq is not able to provide a protocol - I'll develop something
> on my own.

The start of you reply, which I marked with (*), as well as the
paragraph above, do not answer my question: what hypotheses did you
consider and test for apart from an assumption of outside DNS
misbehavior?

Rather than develop an ad hoc patch aimed at confirming your suspicion,
and which will not provide sufficient information until you basically
make it do what tcpdump does, I would, again, suggest running tcpdump
on the machine which hosts the dnsmasq instance, filtering for all DNS
packets (both between LAN and dnsmasq instance and between dnsmasq
instance and upstream servers) and look into the tcpdump log for
anything that looks weird; then try and come up with an explanation for
the weirdness, and test that explanation beyond doubt and assumption.

> Regards,
> Manfred