The issue I am facing: My PiHole setup works without any issues. But I noticed when looking at pihole-FTL.log file that it is full of the following error message.
...
[2022-02-15 00:29:19.191 25294M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 43
[2022-02-15 00:30:27.244 25294M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 43
[2022-02-15 00:33:04.697 25294M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 43
...
I want to resolve the issue so I don't keep getting this message. But I'm also curious if this is something that I can just ignore. I don't have much knowledge or experience with dnsmasq, but I am aware that port 43 is used for whois queries. Maybe someone that can help teach me something new here
Details about my system: Regular Raspberry Pi 3b+ system. It is configured to receive IP from DHCP server (router), but the DHCP server is configured to give the system a static lease. System is also running UFW for security because I have PiVPN. UFW allows all outgoing traffic from RPI, only blocks incoming traffic.
What I have changed since installing Pi-hole: My PiHole setup is fairly simple. I have a regular PiHole setup, but I have added some adlists that gravity is subscribing to. These works without any issues. I am also using cloudflared proxy for DoH so all my DNS queries are forwarded to port 5053 on localhost, and the script will then forward those queries to cloudflare port 53. This also works without any issues, however I am conviced that port 5053 of cloudflared is related to the above mentioned issue.
Same behavior for mine, and I use Quad9 as my upstream DNS:
ERR: Port mismatch for 149.112.112.112: we derived 53, dnsmasq told us 43
ERR: Port mismatch for 9.9.9.9: we derived 53, dnsmasq told us 43
Looking back through my pihole-FTL logs, this error first appeared at 2022-02-13 19:14:04 and was accompanied by a ton of alternating "Gravity database is busy (whitelist)" and "Gravity database is busy (blacklist)" messages. Then at 2022-02-13 19:14:57 those messages stopped but the "Port mismatch" errors continued.
Attached is my pihole-FTL.log for reference back when this first started.
EDIT: I can confirm this issue is tied to FTL v5.14. I was on v5.13 with no issues, then upgraded to 5.14 and restarted. Only then did the issues start (I attached an updated pihole-FTL log file illustrating this).
You might be onto something. I didn't really check when I began to get the port mismatch logs. I rarely check my system since I have unattended-upgrades and some cronjobs setup. But I don't have cronjobs for pihole since it isn't recommend. So I only noticed this because I did a manual pihole upgrade which upgraded FTL from v5.11 to v5.14, and then I was looking through my system to make sure everything else is fine and dandy.
This warning is indeed only available from v5.14 on as we use a new API in dnsmasq that makes deriving the port easier. Apparently, it doesn't always work an we're printing this warning as we're still using our "old" way to deriving the port directly from the packet sent upstream instead of 100% trusting this new API. Which seems to be the right thing!
Thank you for the pihole-FTL.log excerpt, could you also give us the corresponding lines from pihole.log happening at this time? I would like to see if there dnsmasq indeed incorrectly reports the upstream port. Seeing which messages are affected (it seems to be the case only for a few queries, not all of them, right?) should help us a lot in finding where this comes from.
I just logged in to RPI and got both the pihole.log file, and pihole-FTL.log file. Don't feel confident to share the pihole.log file on the internet though since it contains lots of DNS queries. Anywhere I can share it privately?
The log files were quite big (137 MB), so I used regex on both to reduce the contents to only show 2 hours worth of logs. So both log files begin 20:58 and ends 23:02.
I noticed that sometimes the dnsmasq "Err: Port mismatch" messages points to port 48.
Thanks. Unfortunately, this doesn't reveal what it is happening.
Please add
DEBUG_QUERIES=true
DEBUG_FLAGS=true
to the file /etc/pihole/pihole-FTL.conf (create if it does not exist) and run
pihole restartdns
When you see the warning again, please upload another pihole-FTL.log excerpt. We don't need the full big file just a few of these warnings should suffice. The log will will be a lot more verbose with the debug options enabled.
You can easily limit the upload to, say, only the last 500 lines by using something like
I'll reupload more logs later today then with the debug variables set to TRUE. Can't do it right now since I'm currently at work. Thank you for the helpful tips
Hello, and sorry for the delay! I configured the DEBUG variables set to true as you said. Pi-Hole has been running for more than 4 hours since. I did run the tricorder command that you sent me and I have included link below, but I don't think it caught the error. So I'm pasting some interesting lines of the logfile here instead. To me, the issue seems to be at src/dnsmasq/forward.c:541 when a new DNSSEC Query is made.
This is indeed interesting and gives a first idea of what is the issue (DNSSEC retries being analyzed insufficiently). Good news is that this should indeed not have any influence at all on DNS operation, but we should still improve on handling this kind of duplicates.
Could you also quote the related lines from /var/log/pihole.log for the three entries you have pasted above?
You should be able to find them more easily using something like
I ran your grep command on pihole.log.1 so that I can look through the entries for yesterday. However, the grep -C 4 wasn't enough and it included too many non-relevant entries if I increased it. So I went through the log file instead and copy pasted only the relevant entries.
Log Entry 1:
Feb 21 22:00:56 dnsmasq[8991]: dnssec-query[DS] cloudflare.com to 127.0.0.1#5053
Feb 21 22:00:57 dnsmasq[8991]: reply cloudflare.com is DS keytag 2371, algo 13, digest 2
Feb 21 22:00:57 dnsmasq[8991]: dnssec-query[DS] cdnjs.cloudflare.com to 127.0.0.1#5053
Feb 21 22:00:57 dnsmasq[8991]: dnssec-query[DNSKEY] cloudflare.com to 127.0.0.1#5053
Feb 21 22:00:57 dnsmasq[8991]: query[A] cdnjs.cloudflare.com from 192.168.1.205
Feb 21 22:00:57 dnsmasq[8991]: dnssec-retry[DNSKEY] cloudflare.com to 127.0.0.1
Feb 21 22:00:57 dnsmasq[8991]: reply cloudflare.com is DNSKEY keytag 34505, algo 13
Feb 21 22:00:57 dnsmasq[8991]: reply cloudflare.com is DNSKEY keytag 2371, algo 13
Feb 21 22:00:57 dnsmasq[8991]: reply cdnjs.cloudflare.com is DS keytag 2371, algo 13, digest 2
Feb 21 22:00:57 dnsmasq[8991]: dnssec-query[DNSKEY] cdnjs.cloudflare.com to 127.0.0.1#5053
Feb 21 22:00:57 dnsmasq[8991]: reply cdnjs.cloudflare.com is DNSKEY keytag 34505, algo 13
Feb 21 22:00:57 dnsmasq[8991]: reply cdnjs.cloudflare.com is DNSKEY keytag 2371, algo 13
Feb 21 22:00:57 dnsmasq[8991]: validation result is SECURE
Feb 21 22:00:57 dnsmasq[8991]: reply cdnjs.cloudflare.com is 104.16.19.94
Feb 21 22:00:57 dnsmasq[8991]: reply cdnjs.cloudflare.com is 104.16.18.94
Log Entry 2:
--
Feb 21 22:02:18 dnsmasq[8991]: dnssec-query[DS] microsoft.net to 127.0.0.1#5053
Feb 21 22:02:18 dnsmasq[8991]: reply bing.com is no DS
Feb 21 22:02:18 dnsmasq[8991]: dnssec-query[DS] a-msedge.net to 127.0.0.1#5053
Feb 21 22:02:18 dnsmasq[8991]: query[A] cxcs.microsoft.net from 192.168.1.205
Feb 21 22:02:18 dnsmasq[8991]: dnssec-retry[DS] microsoft.net to 127.0.0.1
Feb 21 22:02:18 dnsmasq[8991]: query[A] www.bing.com from 192.168.1.205
Feb 21 22:02:18 dnsmasq[8991]: dnssec-retry[DS] a-msedge.net to 127.0.0.1
Feb 21 22:02:18 dnsmasq[8991]: reply a-msedge.net is no DS
Feb 21 22:02:18 dnsmasq[8991]: validation result is INSECURE
Feb 21 22:02:18 dnsmasq[8991]: reply www.bing.com is <CNAME>
Feb 21 22:02:18 dnsmasq[8991]: reply a-0001.a-afdentry.net.trafficmanager.net is <CNAME>
--
Log Entry 3:
Feb 21 21:15:09 dnsmasq[8991]: query[A] gateway.discord.gg from 192.168.1.120
Feb 21 21:15:09 dnsmasq[8991]: forwarded gateway.discord.gg to 127.0.0.1#5053
Feb 21 21:15:09 dnsmasq[8991]: dnssec-query[DS] gg to 127.0.0.1#5053
Feb 21 21:15:09 dnsmasq[8991]: reply gg is DS keytag 4975, algo 8, digest 2
Feb 21 21:15:09 dnsmasq[8991]: dnssec-query[DS] discord.gg to 127.0.0.1#5053
Feb 21 21:15:09 dnsmasq[8991]: query[A] gateway.discord.gg from 192.168.1.120
Feb 21 21:15:09 dnsmasq[8991]: dnssec-retry[DS] discord.gg to 127.0.0.1
Feb 21 21:15:09 dnsmasq[8991]: dnssec-query[DNSKEY] gg to 127.0.0.1#5053
Feb 21 21:15:09 dnsmasq[8991]: reply gg is DNSKEY keytag 51343, algo 8
Feb 21 21:15:09 dnsmasq[8991]: reply gg is DNSKEY keytag 4975, algo 8
Feb 21 21:15:09 dnsmasq[8991]: reply discord.gg is no DS
Feb 21 21:15:09 dnsmasq[8991]: validation result is INSECURE
Feb 21 21:15:09 dnsmasq[8991]: reply gateway.discord.gg is 162.159.135.234
Feb 21 21:15:09 dnsmasq[8991]: reply gateway.discord.gg is 162.159.136.234
Feb 21 21:15:09 dnsmasq[8991]: reply gateway.discord.gg is 162.159.133.234
Feb 21 21:15:09 dnsmasq[8991]: reply gateway.discord.gg is 162.159.130.234
Feb 21 21:15:09 dnsmasq[8991]: reply gateway.discord.gg is 162.159.134.234
Okay, thanks. We see that the port where we're sending the dnssec-retry to (#5053) is missing here:
whereas it is included for all other queries, such as:
This is a bug in the embedded dnsmasq code. It affects FTL as well, however, FTL is still able to get the port using other means. Nevertheless, this secondary "reverse-engineering" of the port is what is triggering this message you have reported here.
This can only be solved with a bugfix to the dnsmasq code as well.
Please try
pihole checkout ftl fix/dnssec-retry
If you are running Pi-hole in a docker container, you have to be using the dev or nightly containers for the checkout command to be supported.
After the checkout, please grep again for dnssec-retry and check whether the port is now appended to the upstream IP address and the port mismatch error disappeared from pihole-FTL.log.
I ran the command on my Pi-Hole, it's running on a regular Raspberry Pi setup. It's now on the "fix/dnssec-retry" branch. I just ran the command so I don't have any logs generated yet to verify the problem is solved. I'll let it run for now and look through the pihole-FTL.log file sometime tomorrow