[Dnsmasq-discuss] Logging milliseconds

[m***@manfbraun.de]

Hello !

I am just facing the situation, that my dns-request needing a very long
time, and this is wether my requesting client, nor dnsmasq. It's the
provider trying my attempt to ignore his DNSs and use free DNSs,
as we have several here in Germany.

Its not a whole week gone, when I opened an issue about DNS blocking.
It was that, I have enough facts - I'll not try to write whole story here.
But at that last issue, I found me in the situation, where I want to
analyse dnsmasq's log.

I am missing [wrote about that here more then a year ago:
DNSMASQ log output format] the relationship between a clients
request and dnsmasq's answer to it. There can be several in
progress ... From the log, you'll not see it.

Today, due to the DNS blocking story, I want to make a stats over
the log, but it contains only seconds in the timestamp, were I
wished it to have milliseconds too. Is that possible ? I cannot
find something about this.

Additionally, at best, I would fetch the output, if I start the
process by myself and pipe its output directly. Probably not
doable for me. I would write a mini program in C# ... Another
solution would be, to create a pipe in the filesystem and define
it as the logfile for the dnsmasq. I have done this, at least with
apache, it works (Apache has the charm, to be able to host
a program und pump it's output into it - but thats easy for me).

Wether or not, without milliseconds, it would be sensless.

Any help, notes and hints are very welcome !!

Thanks anyway,

[Albert ARIBAUD]

Hi,

Le Mon, 20 Jun 2016 13:13:26 +0200

Post by m***@manfbraun.de
Hello !
I am just facing the situation, that my dns-request needing a very
long time, and this is wether my requesting client, nor dnsmasq. It's
the provider trying my attempt to ignore his DNSs and use free DNSs,
as we have several here in Germany.
Its not a whole week gone, when I opened an issue about DNS blocking.
It was that, I have enough facts - I'll not try to write whole story
here. But at that last issue, I found me in the situation, where I
want to analyse dnsmasq's log.
DNSMASQ log output format] the relationship between a clients
request and dnsmasq's answer to it. There can be several in
progress ... From the log, you'll not see it.
Today, due to the DNS blocking story, I want to make a stats over
the log, but it contains only seconds in the timestamp, were I
wished it to have milliseconds too. Is that possible ? I cannot
find something about this.
Additionally, at best, I would fetch the output, if I start the
process by myself and pipe its output directly. Probably not
doable for me. I would write a mini program in C# ... Another
solution would be, to create a pipe in the filesystem and define
it as the logfile for the dnsmasq. I have done this, at least with
apache, it works (Apache has the charm, to be able to host
a program und pump it's output into it - but thats easy for me).
Wether or not, without milliseconds, it would be sensless.
Any help, notes and hints are very welcome !!

If you can run wireshark or even simply tcpdump on the machine that runs
dnsmasq, then you could log DNS requests and replies with accurate time
stamping. Would this be enough for you?

Post by m***@manfbraun.de
Thanks anyway,

Amicalement,

[m***@manfbraun.de]

Hello !

Ok, for a short moment, this might be ok. But request/response usually
dont follow each other directly, because there are some more of them
"on the road". DNSMasq has already all this internally, while externally,
one must really write a piece of tracker, which is able to wait for the
answer of each request. Not a nice bash onliner .. ;-)

But my question was just, if something like a format statement for the
logoutput exists. It this exist (and I do not see it) then everything is
already done.

It's because I see huge delay for apps nearly each day. The provider
declared to have the issue fixed. Sort of. The port are not longer
blocked - but now, there are huge delay. The may probably have
a contract with the NSA .... ;-)

Thanks anyway,

Manfred

-----Original Message-----
Sent: Monday, June 20, 2016 3:09 PM
Subject: Re: [Dnsmasq-discuss] Logging milliseconds
Hi,
Le Mon, 20 Jun 2016 13:13:26 +0200

Post by m***@manfbraun.de
Hello !
I am just facing the situation, that my dns-request needing a very
long time, and this is wether my requesting client, nor dnsmasq. It's
the provider trying my attempt to ignore his DNSs and use free DNSs,
as we have several here in Germany.
Its not a whole week gone, when I opened an issue about DNS blocking.
It was that, I have enough facts - I'll not try to write whole story
here. But at that last issue, I found me in the situation, where I
want to analyse dnsmasq's log.
DNSMASQ log output format] the relationship between a clients
request and dnsmasq's answer to it. There can be several in
progress ... From the log, you'll not see it.
Today, due to the DNS blocking story, I want to make a stats over
the log, but it contains only seconds in the timestamp, were I
wished it to have milliseconds too. Is that possible ? I cannot
find something about this.
Additionally, at best, I would fetch the output, if I start the
process by myself and pipe its output directly. Probably not
doable for me. I would write a mini program in C# ... Another
solution would be, to create a pipe in the filesystem and define
it as the logfile for the dnsmasq. I have done this, at least with
apache, it works (Apache has the charm, to be able to host
a program und pump it's output into it - but thats easy for me).
Wether or not, without milliseconds, it would be sensless.
Any help, notes and hints are very welcome !!

If you can run wireshark or even simply tcpdump on the machine that runs
dnsmasq, then you could log DNS requests and replies with accurate time
stamping. Would this be enough for you?

Post by m***@manfbraun.de
Thanks anyway,

Amicalement,
--
Albert.

[Albert ARIBAUD]

This post might be inappropriate. Click to display it.

[m***@manfbraun.de]

This post might be inappropriate. Click to display it.

[Albert ARIBAUD]

Hi Manfred,

Le Tue, 21 Jun 2016 18:25:44 +0200

Post by m***@manfbraun.de
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 (*)

Post by m***@manfbraun.de
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
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.

Post by m***@manfbraun.de
Has nothing to do with other apps-delays.
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.

Post by m***@manfbraun.de
Regards,
Manfred

[Rick Jones]

Post by Albert ARIBAUD
Why 'for a short moment'? The only limit is storage for the tcpdump
dump to file, and that's relatively dense. Even if the machine on which
you are running tcpdump does not have enough storage space, it could
always send the output over the network to e.g. your desktop or laptop
machine, which is certainly able to handle it.

One does though want to make certain the "forwarded tcpdump" has a
filter expression sufficient to keep tcpdump from capturing the traffic
of the forwarded tcpdump capture... :)

happy benchmarking,

rick jones