Pihole-FTL.log is full of "ERR: Port mismatch" log entries

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?

If they are relatively small then you can echo them to pihole tricorder and post the token url.

cat thisfile.log | pihole tricorder

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.

Here is tricorder link to pihole.log: https://tricorder.pi-hole.net/Xdny4dJv/
and here is just the pihole-FTL.log: https://tricorder.pi-hole.net/DNeTCHGn/

2 Likes

I see them both, thanks!

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

tail -n 500 < /var/log/pihole-FTL.log | pihole tricorder

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 :slight_smile:

1 Like

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.

Pihole-FTL.log: https://tricorder.pi-hole.net/A51cN30x/

Log Entry 1:

[2022-02-21 22:00:57.044 8991M] **** new IPv4 dnssec-query[DNSKEY] query "cloudflare.com" from -/<internal>#53 (ID 16565, FTL 39381, src/dnsmasq/forward.c:541)
[2022-02-21 22:00:57.044 8991M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 48
[2022-02-21 22:00:57.044 8991M] **** forwarded cloudflare.com to 127.0.0.1#5053 (ID 16565, src/dnsmasq/forward.c:541)
[2022-02-21 22:00:57.044 8991M] Processing FTL hook from src/dnsmasq/forward.c:1623...
[2022-02-21 22:00:57.044 8991M]      Flags: F_FORWARD F_IPV4 F_QUERY

Log Entry 2:

[2022-02-21 22:02:18.883 8991M] **** new IPv4 dnssec-query[DS] query "a-msedge.net" from -/<internal>#53 (ID 16842, FTL 39464, src/dnsmasq/forward.c:541)
[2022-02-21 22:02:18.884 8991M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 43
[2022-02-21 22:02:18.884 8991M] **** forwarded a-msedge.net to 127.0.0.1#5053 (ID 16842, src/dnsmasq/forward.c:541)
[2022-02-21 22:02:18.885 8991M] Processing FTL hook from src/dnsmasq/dnssec.c:1122...
[2022-02-21 22:02:18.885 8991M]      Flags: F_UPSTREAM F_NOEXTRA

[2022-02-21 22:02:18.885 8991M] **** got upstream reply from 127.0.0.1#5053: a-msedge.net is no DS (ID 16842, src/dnsmasq/dnssec.c:1122)
[2022-02-21 22:02:18.885 8991M] Set reply to NODATA (1) in src/dnsmasq_interface.c:2128
[2022-02-21 22:02:18.885 8991M] Processing FTL hook from src/dnsmasq/forward.c:1230...
[2022-02-21 22:02:18.886 8991M]      Flags: F_SECSTAT

Log Entry 3:

[2022-02-21 21:15:09.368 8991M] **** new IPv4 dnssec-query[DS] query "discord.gg" from -/<internal>#53 (ID 11461, FTL 39801, src/dnsmasq/forward.c:541)
[2022-02-21 21:15:09.368 8991M] ERR: Port mismatch for 127.0.0.1: we derived 5053, dnsmasq told us 43
[2022-02-21 21:15:09.368 8991M] **** forwarded discord.gg to 127.0.0.1#5053 (ID 11461, src/dnsmasq/forward.c:541)
[2022-02-21 21:15:09.377 8991M] Processing FTL hook from src/dnsmasq/forward.c:979...
[2022-02-21 21:15:09.377 8991M]      Flags: F_IPV4 F_SERVER F_DNSSEC F_NOEXTRA

[2022-02-21 21:15:09.377 8991M] **** new IPv4 dnssec-query[DNSKEY] query "gg" from -/<internal>#53 (ID 11463, FTL 39802, src/dnsmasq/forward.c:979)
[2022-02-21 21:15:09.377 8991M] **** forwarded gg to 127.0.0.1#5053 (ID 11463, src/dnsmasq/forward.c:979)
[2022-02-21 21:15:09.384 8991M] Processing FTL hook from src/dnsmasq/dnssec.c:958...
[2022-02-21 21:15:09.384 8991M]      Flags: F_UPSTREAM F_KEYTAG F_NOEXTRA
[2022-02-21 21:15:09.384 8991M] **** got upstream reply from 127.0.0.1#5053: gg is DNSKEY (ID 11463, src/dnsmasq/dnssec.c:958)
[2022-02-21 21:15:09.384 8991M] Set reply to DNSSEC (11) in src/dnsmasq_interface.c:2128
[2022-02-21 21:15:09.384 8991M] Processing FTL hook from src/dnsmasq/dnssec.c:958...
[2022-02-21 21:15:09.384 8991M]      Flags: F_UPSTREAM F_KEYTAG F_NOEXTRA

[2022-02-21 21:15:09.384 8991M] **** got upstream reply from 127.0.0.1#5053: gg is DNSKEY (ID 11463, src/dnsmasq/dnssec.c:958)
[2022-02-21 21:15:09.386 8991M] Processing FTL hook from src/dnsmasq/dnssec.c:1122...
[2022-02-21 21:15:09.386 8991M]      Flags: F_UPSTREAM F_NOEXTRA
[2022-02-21 21:15:09.386 8991M] **** got upstream reply from 127.0.0.1#5053: discord.gg is no DS (ID 11461, src/dnsmasq/dnssec.c:1122)
[2022-02-21 21:15:09.386 8991M] Set reply to NODATA (1) in src/dnsmasq_interface.c:2128
[2022-02-21 21:15:09.386 8991M] Processing FTL hook from src/dnsmasq/forward.c:1230...
[2022-02-21 21:15:09.386 8991M]      Flags: F_SECSTAT

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

grep -C 4 "dnssec-retry" /var/log/pihole.log

if my current hypothesis is correct.

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.

1 Like

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 :slight_smile:

Worked for me. The dnsmasq process wasn't answering any requests until I applied this branch.

Any news for us?

Hello and sorry for the delay.

I've looked through the logs and everything seems fine now. No longer receiveing any Port Mismatch errors in pihole-FTL.log :slight_smile:

cat /var/log/pihole-FTL.log
[2022-03-02 00:20:27.548 11174M] Resizing "FTL-dns-cache" from 274432 to (17408 * 16) == 278528 (/dev/shm: 3.8MB used, 484.0MB total, FTL uses 3.8MB)
[2022-03-02 01:30:06.163 11174M] Resizing "FTL-dns-cache" from 278528 to (17664 * 16) == 282624 (/dev/shm: 3.8MB used, 484.0MB total, FTL uses 3.8MB)
[2022-03-02 04:26:10.747 11174M] Resizing "FTL-dns-cache" from 282624 to (17920 * 16) == 286720 (/dev/shm: 3.8MB used, 484.0MB total, FTL uses 3.8MB)
[2022-03-02 04:51:06.846 11174M] Resizing "FTL-queries" from 2162688 to (53248 * 44) == 2342912 (/dev/shm: 3.8MB used, 484.0MB total, FTL uses 3.8MB)
[2022-03-02 09:00:12.423 11174M] Resizing "FTL-domains" from 184320 to (10240 * 20) == 204800 (/dev/shm: 4.0MB used, 484.0MB total, FTL uses 4.0MB)
[2022-03-02 17:39:45.688 11174M] Resizing "FTL-dns-cache" from 286720 to (18176 * 16) == 290816 (/dev/shm: 4.0MB used, 484.0MB total, FTL uses 4.0MB)
[2022-03-02 18:18:24.433 11174M] Received: Real-time signal 0 (34 -> 0)
[2022-03-02 18:18:24.949 11174/T11178] Compiled 0 whitelist and 1 blacklist regex filters for 25 clients in 133.3 msec
[2022-03-02 18:18:26.008 11174M] Blocking status is disabled
[2022-03-02 18:18:38.686 11174M] Resizing "FTL-strings" from 286720 to (327680 * 1) == 327680 (/dev/shm: 4.0MB used, 484.0MB total, FTL uses 4.0MB)
[2022-03-02 18:23:24.522 11174M] Received: Real-time signal 0 (34 -> 0)
[2022-03-02 18:23:25.098 11174/T11178] Compiled 0 whitelist and 1 blacklist regex filters for 25 clients in 119.6 msec
[2022-03-02 18:23:26.642 11174M] Blocking status is enabled
[2022-03-02 18:39:19.748 11174M] Resizing "FTL-dns-cache" from 290816 to (18432 * 16) == 294912 (/dev/shm: 4.0MB used, 484.0MB total, FTL uses 4.0MB)
[2022-03-02 21:07:22.055 11174M] Resizing "FTL-dns-cache" from 294912 to (18688 * 16) == 299008 (/dev/shm: 4.0MB used, 484.0MB total, FTL uses 4.0MB)

Thanks for your feedback an no worries about the delay, we're all busy at times.

One last thing, could you check if the dnssec-query[DS] lines show the correct port now in /var/log/pihole.log ?

I checked pihole.log and pihole.log.1. They both seem to always show the correct port now. Pasting some output below.

--
Mar 10 17:25:18 dnsmasq[11174]: query[A] www.southparkstudios.nu from 192.168.1.181
Mar 10 17:25:18 dnsmasq[11174]: forwarded www.southparkstudios.nu to 127.0.0.1#5053
Mar 10 17:25:18 dnsmasq[11174]: validation result is INSECURE
Mar 10 17:25:18 dnsmasq[11174]: dnssec-query[DS] nu to 127.0.0.1#5053
--
Mar 10 23:39:25 dnsmasq[11174]: query[A] gossip.easyanticheat.net from 192.168.1.120
Mar 10 23:39:25 dnsmasq[11174]: forwarded gossip.easyanticheat.net to 127.0.0.1#5053
Mar 10 23:39:25 dnsmasq[11174]: dnssec-query[DS] easyanticheat.net to 127.0.0.1#5053
Mar 10 23:39:25 dnsmasq[11174]: query[A] gossip.easyanticheat.net from 192.168.1.120
Mar 10 23:39:25 dnsmasq[11174]: dnssec-retry[DS] easyanticheat.net to 127.0.0.1#5053
Mar 10 23:39:25 dnsmasq[11174]: reply easyanticheat.net is no DS
Mar 10 23:39:25 dnsmasq[11174]: dnssec-query[DS] eac-front.com to 127.0.0.1#5053
Mar 10 23:39:25 dnsmasq[11174]: reply eac-front.com is no DS
Mar 10 23:39:25 dnsmasq[11174]: validation result is INSECURE
--
Mar 11 04:52:47 dnsmasq[11174]: query[A] api.spotify.com from 192.168.1.120
Mar 11 04:52:47 dnsmasq[11174]: forwarded api.spotify.com to 127.0.0.1#5053
Mar 11 04:52:47 dnsmasq[11174]: dnssec-query[DS] spotify.com to 127.0.0.1#5053
Mar 11 04:52:47 dnsmasq[11174]: query[A] api.spotify.com from 192.168.1.120
Mar 11 04:52:47 dnsmasq[11174]: dnssec-retry[DS] spotify.com to 127.0.0.1#5053
Mar 11 04:52:47 dnsmasq[11174]: reply spotify.com is no DS
Mar 11 04:52:47 dnsmasq[11174]: validation result is INSECURE
Mar 11 04:52:47 dnsmasq[11174]: reply api.spotify.com is <CNAME>
Mar 11 04:52:47 dnsmasq[11174]: reply edge-web.dual-gslb.spotify.com is 35.186.224.25
--
1 Like

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.