Re: [Dnsmasq-discuss] Logging milliseconds//Addendum
Hi ! Many thanks for your investigation !!! I'll not bother you or anyone in any way, but we may just have different perspectives to see the problem. I just tell my opinion about the log - noone should start to patch something. I am also the type, which waits for distro updates ... to shy to install from source. My log-example was mainly to show, that DNSMasq COULD give a better help through it logs - it was not thought to explain the problem. That, what you asked to me, exactly that - so I think - should answer the log ... pobably, one day. I think, I have good control over my environment and I ensure, if I make tests like my DNS tests, that the line is not loaded ! The log-example stems just from real-live, were countless apps are running and different computer are up. There is, for example, a RSS reader, which starts batch-loads for a big list of websites - just to explain, why I do not wonder about the logfile. There is much more, like over 20 Virusprotection solution, which updates every hour ... So I'll start to make a tool, which systematically answers some (all known open/free DNS in Germany) and measure the overall response. Will need some time, so. In the meantime, I am using the DNS from the ISP - anyway what may cause the problem, if I use the DNS from ISP, I never have problems at all . !!! If this would not be the case, I really would also suspect DNSMasq (indirectly), because this runs on a stonehenge old box, with really no memory free I see in my syslog, the Nagios command sometimes fail, due to not enough memory. This cannot be fixed very fast - too many thing on my list. But a new firewall machine is already on the table ... Thanks again and my best regards, Manfred [I hope, this "reply all" will not cause another thread ...] > -Original Message- > From: Albert ARIBAUD [mailto:albert.arib...@free.fr] > Sent: Tuesday, June 21, 2016 8:05 PM > To: ma...@manfbraun.de > Cc: dnsmasq-discuss@lists.thekelleys.org.uk > Subject: Re: [Dnsmasq-discuss] Logging milliseconds//Addendum > > Hi Manfred, > > Le Tue, 21 Jun 2016 17:30:13 +0200 > <ma...@manfbraun.de> a écrit: > > > Hi All ! > > > > I just changed some free DNS against some other free DNS > > and now, I have more problems then bevore. Though I'll > > extend my logging thoughs: In the DNSMasq answer is not > > visible which of dns provided the answer - that makes diag > > problematic. > > Seems you started a new thread while I was answering on the previous > one. > > Short answer: I would suggest that you avoid trying "this and that" as > well as ad hoc patching", and that you follow a more systematic approach > to solving your problem, by running tcpdump on the machine which hosts > your dnsmasq. > > Also, you should really try and make other hypotheses than just your ISP > messing with DNS. For instance, have you tried to find out how much of > your uplink bandwidth you're using? Because if your uplink saturates, > then UDP packets sch as DNS requests might get dropped by your ISP's > modem. > > > Thanks anyway, > > Manfred > > Amicalement, > -- > Albert. ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Re: [Dnsmasq-discuss] Logging milliseconds
On 06/21/2016 08:36 AM, Albert ARIBAUD wrote: 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 ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Re: [Dnsmasq-discuss] Logging milliseconds//Addendum
Hi Manfred, Le Tue, 21 Jun 2016 17:30:13 +0200a écrit: > Hi All ! > > I just changed some free DNS against some other free DNS > and now, I have more problems then bevore. Though I'll > extend my logging thoughs: In the DNSMasq answer is not > visible which of dns provided the answer - that makes diag > problematic. Seems you started a new thread while I was answering on the previous one. Short answer: I would suggest that you avoid trying "this and that" as well as ad hoc patching", and that you follow a more systematic approach to solving your problem, by running tcpdump on the machine which hosts your dnsmasq. Also, you should really try and make other hypotheses than just your ISP messing with DNS. For instance, have you tried to find out how much of your uplink bandwidth you're using? Because if your uplink saturates, then UDP packets sch as DNS requests might get dropped by your ISP's modem. > Thanks anyway, > Manfred Amicalement, -- Albert. ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Re: [Dnsmasq-discuss] Logging milliseconds
Hi Manfred, Le Tue, 21 Jun 2016 18:25:44 +0200a é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[] 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. >
Re: [Dnsmasq-discuss] Logging milliseconds
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. 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[] 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. 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. Regards, Manfred > -Original Message- > From: Albert ARIBAUD [mailto:albert.arib...@free.fr] > Sent: Tuesday, June 21, 2016 5:36 PM > To: ma...@manfbraun.de > Cc: dnsmasq-discuss@lists.thekelleys.org.uk > Subject: Re: [Dnsmasq-discuss] Logging milliseconds > > Bonjour, > > Le Tue, 21 Jun 2016 16:41:02 +0200 > <ma...@manfbraun.de> a écrit: > > > Hello ! > > > > Ok, for a short moment, this might be ok. > > 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. > > > 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 .. ;-) > > Wireshark is able to map responses to requests; in fact, in the packet > display window, it provides clickable links to jump from one to the > other. Wireshark also computes the time elapsed between request and > response, and displays it in the response packet
Re: [Dnsmasq-discuss] Logging milliseconds
Bonjour, Le Tue, 21 Jun 2016 16:41:02 +0200a écrit: > Hello ! > > Ok, for a short moment, this might be ok. 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. > 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 .. ;-) Wireshark is able to map responses to requests; in fact, in the packet display window, it provides clickable links to jump from one to the other. Wireshark also computes the time elapsed between request and response, and displays it in the response packet. And you can export all this as text, including references between requests and responses and their time deltas. Granted, if you want to do stats on long capture logs (or just limit the dump to what you think is valuable), you'll have to write some ad hoc AWK or sed lines, but I'd suspect a few tens at most, and nothing more complex than variable assignments, some arithmetic, and ouput formattting. > 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. I don't think there is any log format control option in dnsmasq. > 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 ;-) "Delays in apps" can have so many causes. What possible causes other than remote DNS servers have you considered and how did you rule them out? > Thanks anyway, > > Manfred Amicalement, -- Albert. ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Re: [Dnsmasq-discuss] Logging milliseconds
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- > From: Albert ARIBAUD [mailto:albert.arib...@free.fr] > Sent: Monday, June 20, 2016 3:09 PM > To: ma...@manfbraun.de > Cc: dnsmasq-discuss@lists.thekelleys.org.uk > Subject: Re: [Dnsmasq-discuss] Logging milliseconds > > Hi, > > Le Mon, 20 Jun 2016 13:13:26 +0200 > <ma...@manfbraun.de> a écrit: > > > 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 !! > > 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? > > > Thanks anyway, > > Amicalement, > -- > Albert. ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
Re: [Dnsmasq-discuss] Logging milliseconds
Hi, Le Mon, 20 Jun 2016 13:13:26 +0200a écrit: > 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 !! 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? > Thanks anyway, Amicalement, -- Albert. ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss
[Dnsmasq-discuss] Logging milliseconds
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, ___ Dnsmasq-discuss mailing list Dnsmasq-discuss@lists.thekelleys.org.uk http://lists.thekelleys.org.uk/mailman/listinfo/dnsmasq-discuss