search

pi-hole / FTL

The Pi-hole FTL engine
https://pi-hole.net
Other
1.34k stars 187 forks source link

PTR requests not being generated for local clients #1975

Closed moya2162 closed 1 month ago

moya2162 commented 1 month ago

Versions

Core Version is 250a44c (Latest: null) Branch is development-v6 Hash is 250a44ca (Latest: N/A) Web Version is 59b1dcf (Latest: null) Branch is development-v6 Hash is 59b1dcfc (Latest: N/A) FTL Version is vDev-825a14a (Latest: null) Branch is development-v6 Hash is 825a14a6 (Latest: N/A)

Platform

Expected behavior

Pi-Hole should be issuing PTR request for clients to be forwarded upstream.

Actual behavior / bug

Pi-Hole is not issuing PTR requests. Enabled debug.resolver and following error is repeating for all my local clients, both ipv4 and ipv6:

2024-05-25 13:43:23.450 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "192.168.X.XX"
2024-05-25 13:44:14.303 DEBUG_RESOLVER  ---> not found
2024-05-25 13:44:14.304 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "2601:204:0:XXXX:XXXX:XXXX:XXXX:XXXX"
2024-05-25 13:45:15.840 DEBUG_RESOLVER  ---> not found
2024-05-25 13:45:15.842 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "fd71:2002:f23:0:XXXX:XXXX:XXXX:XXXX"
2024-05-25 13:45:15.846 DEBUG_RESOLVER  ---> not found

Additional Info

DL6ER commented 1 month ago

What your are quoting isn't an error, it is just a message telling you that the respective client's name is not yet in the database.

Please check the log at full hour to see the resolving attempts. Looking at you configuration, I do wonder who should reply to you PTRs upstream? You do not have revServers set, nor use DHCP in Pi-hole, and only use unbound as upstream. Do you expect unbound to reply to your 192.168.x.y PTR requests?

moya2162 commented 1 month ago

Unbound handles my conditional forwarding. My router handles the PTR replies.

I do not see Pihole sending out PTR requests other than a single ipv6 local address and it is of the pihole host device. I have Unbound configured to drop ipv6 PTR requests and prefer to rely on on resolver.networkNames and dns.EDNS0ECS to resolve hostnames of ipv6 devices.

The way i used to test this in v5 was to restart piholes dns server from the Settings page. Upon restart all initial PTR requests got sent out. This time around i only see a single PTR request mentioned above.

Edit-----

When i run nslookup [DEVICE] [PIHOLE] on my computer i get the correct hostname reply so PTR forwarding is working correctly. It just seems like Pihole is not running its own PTR request to resolve hostnames of devices. Is it possible I have one of the dns server settings enabled that causes Pihole to stop sending requests? I have resolver.refreshNames=ALL but the logs make it seem like resolver.refreshNames=NONE is set.

DL6ER commented 1 month ago

Thanks for the additional details, it wasn't clear to me before that unbound can indeed answer these requests. Now let's go on with debugging FTL as it seems upstream should be fine.

I'd recommend using

sudo kill -s RTMIN+4 $(cat /run/pihole-FTL.pid)

on your Pi-hole to force a refreshing of host names now. Have a close look on the log files about what is happening. Especially DEBUG_RESOLVER lines in FTL.logand the [PTR] lines in pihole.log are of interest here if you want to use grep to filter the log for easier reading.

resolver.refreshNames is ignored when forcing using the signal as above. Otherwise, if NONE would be used, the debug output would be something like

DEBUG_RESOLVER: Skipping client <ip> (<oldname>) because it should not be refreshed: <reason>

where <reason> could be any of:

DL6ER commented 1 month ago

Example:

sudo pihole-FTL --config debug.resolver true
sudo kill -s RTMIN+4 $(cat /run/pihole-FTL.pid)
grep "DEBUG_RESOLVER" /var/log/pihole/FTL.log

should give you lines like:

...
2024-05-26 10:34:46.472 [931456/T931463] DEBUG_RESOLVER: Trying to resolve 192.168.2.5
2024-05-26 10:34:46.473 [931456/T931463] DEBUG_RESOLVER: Resolving 192.168.2.5 (PTR "5.2.168.192.in-addr.arpa"): 0 = "pi.fritz.box"
2024-05-26 10:34:46.473 [931456/T931463] DEBUG_RESOLVER: Client 192.168.2.5 -> "pi.fritz.box" is new
2024-05-26 10:34:46.473 [931456/T931463] DEBUG_RESOLVER: Skipping client :: (pi.hole) because it should not be refreshed: Only refreshing IPv4 names
2024-05-26 10:34:46.473 [931456/T931463] DEBUG_RESOLVER: Trying to resolve 127.0.0.1
2024-05-26 10:34:46.474 [931456/T931463] DEBUG_RESOLVER: Resolving 127.0.0.1 (PTR "1.0.0.127.in-addr.arpa"): 0 = "localhost.lan"
2024-05-26 10:34:46.474 [931456/T931463] DEBUG_RESOLVER: Client 127.0.0.1 -> "localhost.lan" is new
...
moya2162 commented 1 month ago

So i flushed logs network table restarted dns resolver. I then ran your command above and got the following

FTL.log

2024-05-26 01:43:31.253 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:31.254 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "192.168.2.40"
2024-05-26 01:43:31.304 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:31.305 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "fd71:2002:f23:0:XXXX:XXXX:XXXX:2feb"
2024-05-26 01:43:31.966 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:31.968 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "2601:204:0:cf3c:XXXX:XXXX:XXXX:2feb"
2024-05-26 01:43:32.992 DEBUG_RESOLVER Trying to resolve 192.168.2.102
2024-05-26 01:43:33.002 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:33.005 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "127.0.0.1"
2024-05-26 01:43:33.010 DEBUG_RESOLVER Resolving 192.168.2.102 (PTR "102.2.168.192.in-addr.arpa"): 0 = "XXXXXXX.lan"
2024-05-26 01:43:33.011 DEBUG_RESOLVER Client 192.168.2.102 -> "XXXXXXX.lan" is new
2024-05-26 01:43:33.011 DEBUG_RESOLVER Trying to resolve 192.168.2.40
2024-05-26 01:43:33.017 DEBUG_RESOLVER Resolving 192.168.2.40 (PTR "40.2.168.192.in-addr.arpa"): 0 = "XXXXXXX.lan"
2024-05-26 01:43:33.017 DEBUG_RESOLVER Client 192.168.2.40 -> "XXXXXXX.lan" is new
2024-05-26 01:43:33.018 DEBUG_RESOLVER Trying to resolve fd71:2002:f23:0:XXXX:XXXX:XXXX:2feb
2024-05-26 01:43:33.027 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:33.027 DEBUG_RESOLVER Client fd71:2002:f23:0:XXXX:XXXX:XXXX:2feb -> "" is new
2024-05-26 01:43:33.028 DEBUG_RESOLVER Trying to resolve 2601:204:0:cf3c:XXXX:XXXX:XXXX:2feb
2024-05-26 01:43:37.697 INFO Received: RT39 (39 -> 4)
2024-05-26 01:43:42.531 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:42.532 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "192.168.2.60"
2024-05-26 01:43:51.136 DEBUG_RESOLVER  ---> not found
2024-05-26 01:43:51.138 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "fd71:2002:f23:0:XXXX:XXXX:XXXX:40dd"
2024-05-26 01:44:07.013 DEBUG_RESOLVER  ---> not found
2024-05-26 01:44:07.014 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "2601:204:0:cf3c:XXXX:XXXX:XXXX:9349"
DL6ER commented 1 month ago

And there are no corresponding PTR lines in pihole.log at that time? In this case, what is the content of your /etc/resolv.conf inside the container and outside?

moya2162 commented 1 month ago

Corresponding PTR requests in pihole.log 

May 26 01:43:32 dnsmasq[177]: query[PTR] 102.2.168.192.in-addr.arpa from 127.0.0.1
May 26 01:43:33 dnsmasq[177]: query[PTR] 40.2.168.192.in-addr.arpa from 127.0.0.1
May 26 01:43:33 dnsmasq[177]: query[PTR] b.e.f.2.1.b.8.a.6.b.8.7.8.2.9.a.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa from 127.0.0.1
May 26 01:43:33 dnsmasq[177]: query[PTR] b.e.f.2.1.b.8.a.6.b.8.7.8.2.9.a.c.3.f.c.0.0.0.0.4.0.2.0.1.0.6.2.ip6.arpa from 127.0.0.1

Outside Container /etc/resolv.conf

# Generated by NetworkManager
search lan
nameserver 192.168.2.1
#nameserver 1.1.1.1
nameserver fd71:2002:f23::1
nameserver 2601:204:0:cf3c::1

Inside Container /etc/resolv.conf

# Generated by Docker Engine.
# This file can be edited; Docker Engine will not make further changes once it
# has been modified.

nameserver 127.0.0.11
search lan
options ndots:0

# Based on host file: '/etc/resolv.conf' (internal resolver)
# ExtServers: [192.168.2.1 fd71:2002:f23::1 2601:204:0:cf3c::1]
# Overrides: []
# Option ndots from: internal
DL6ER commented 1 month ago

Are the PTRs you found in pihole.log forwarded? maybe something like

grep '\[PTR\]' /var/log/pihole/pihole.log -A3

would have been a better suggestion.

moya2162 commented 1 month ago

FTL is forwarding PTR request fine. I can nslookup from outside and inside container and i am able to resolve manually.

I have Unbound configured to only forward ipv4 PTR requests and to NXDOMAIN ipv6, as reflected in the log:

May 26 02:09:48 dnsmasq[165]: query[PTR] 102.2.168.192.in-addr.arpa from 127.0.0.1
May 26 02:09:48 dnsmasq[165]: forwarded 102.2.168.192.in-addr.arpa to 172.18.0.143#5053
May 26 02:09:48 dnsmasq[165]: reply 192.168.2.102 is XXXXXXX.lan
May 26 02:09:48 dnsmasq[165]: query[PTR] 40.2.168.192.in-addr.arpa from 127.0.0.1
May 26 02:09:48 dnsmasq[165]: forwarded 40.2.168.192.in-addr.arpa to 172.18.0.143#5053
May 26 02:09:48 dnsmasq[165]: reply 192.168.2.40 is XXXXXXX.lan
May 26 02:09:48 dnsmasq[165]: query[PTR] b.e.f.2.1.b.8.a.6.b.8.7.8.2.9.a.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa from 127.0.0.1
May 26 02:09:48 dnsmasq[165]: forwarded b.e.f.2.1.b.8.a.6.b.8.7.8.2.9.a.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa to 172.18.0.143#5053
May 26 02:09:48 dnsmasq[165]: reply fd71:2002:f23:0:a928:78b6:a8b1:2feb is NXDOMAIN
moya2162 commented 1 month ago

As i understand things, upon a resolver restart FTL should send out PTR request for clients it has recorded in the database based on my settings. There must me a condition set somewhere that its leading to FTL not sending out the PTR request. That is my conclusion based on log results.

DL6ER commented 1 month ago

Yes, it is hard to really tell from my side what is happening because we have seen only small excerpts from the log here, so far. What is not happening as expected is, e.g., what you have shown here. After the

2024-05-26 01:43:37.697 INFO Received: RT39 (39 -> 4)

I'd have expected FTL to start to resolve all client host names which would look like this.

At the very end, we see a line like

grep "client host names" /var/log/pihole/FTL.log
2024-05-26 11:33:44.694 [1139918/T1139922] DEBUG_RESOLVER: 21 / 22 client host names resolved

Do you see such lines in the log file?

moya2162 commented 1 month ago

FTL.log after reset of quarries and network table and restart of resolver. The upstream that its skipping is unbound's container. 

2024-05-26 02:48:29.912 INFO PID of FTL process: 165
2024-05-26 02:48:29.924 INFO listening on 0.0.0.0 port 53
2024-05-26 02:48:29.924 INFO listening on :: port 53
2024-05-26 02:48:29.926 INFO PID of FTL process: 165
2024-05-26 02:48:29.928 INFO Database version is 17
2024-05-26 02:48:29.929 INFO Database successfully initialized
2024-05-26 02:48:29.951 INFO Imported 0 queries from the on-disk database (it has 0 rows)
2024-05-26 02:48:29.951 INFO Parsing queries in database
2024-05-26 02:48:29.951 INFO Imported 0 queries from the long-term database
2024-05-26 02:48:29.951 INFO  -> Total DNS queries: 0
2024-05-26 02:48:29.951 INFO  -> Cached DNS queries: 0
2024-05-26 02:48:29.952 INFO  -> Forwarded DNS queries: 0
2024-05-26 02:48:29.952 INFO  -> Blocked DNS queries: 0
2024-05-26 02:48:29.952 INFO  -> Unknown DNS queries: 0
2024-05-26 02:48:29.952 INFO  -> Unique domains: 0
2024-05-26 02:48:29.952 INFO  -> Unique clients: 0
2024-05-26 02:48:29.952 INFO  -> DNS cache records: 0
2024-05-26 02:48:29.952 INFO  -> Known forward destinations: 0
2024-05-26 02:48:29.952 INFO FTL is running as user pihole (UID 1000)
2024-05-26 02:48:29.953 INFO Reading certificate from /etc/pihole/tls.pem ...
2024-05-26 02:48:29.953 INFO Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-05-26 02:48:29.959 INFO Restored 1 API session from the database
2024-05-26 02:48:29.962 INFO Blocking status is enabled
2024-05-26 02:48:30.058 INFO Compiled 0 allow and 0 deny regex for 0 client in 0.6 msec
2024-05-26 02:48:32.798 DEBUG_RESOLVER  ---> not found
2024-05-26 02:48:32.799 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "fd71:2002:f23::102"
2024-05-26 02:48:32.953 DEBUG_RESOLVER Trying to resolve fd71:2002:f23::102
2024-05-26 02:48:32.958 DEBUG_RESOLVER  ---> not found
2024-05-26 02:48:32.960 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "127.0.0.1"
2024-05-26 02:48:32.966 DEBUG_RESOLVER  ---> not found
2024-05-26 02:48:32.966 DEBUG_RESOLVER Client fd71:2002:f23::102 -> "" is new
2024-05-26 02:48:32.966 DEBUG_RESOLVER 1 / 1 client host names resolved
2024-05-26 02:48:32.967 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716912 seconds
2024-05-26 02:48:32.967 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716912 seconds
2024-05-26 02:48:32.967 DEBUG_RESOLVER 2 / 2 upstream server host names resolved
2024-05-26 02:48:33.968 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it is not new
2024-05-26 02:48:33.968 DEBUG_RESOLVER Trying to resolve 127.0.0.1
2024-05-26 02:48:33.969 DEBUG_RESOLVER Resolving 127.0.0.1 (PTR "1.0.0.127.in-addr.arpa"): 0 = "localhost"
2024-05-26 02:48:33.970 DEBUG_RESOLVER Client 127.0.0.1 -> "localhost" is new
2024-05-26 02:48:33.970 DEBUG_RESOLVER 1 / 2 client host names resolved
2024-05-26 02:48:33.970 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716913 seconds
2024-05-26 02:48:33.970 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716913 seconds
2024-05-26 02:48:33.970 DEBUG_RESOLVER 2 / 2 upstream server host names resolved
2024-05-26 02:49:12.767 INFO Received: RT39 (39 -> 4)
2024-05-26 02:49:13.007 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it should not be refreshed: Only refreshing IPv4 names
2024-05-26 02:49:13.007 DEBUG_RESOLVER Trying to resolve 127.0.0.1
2024-05-26 02:49:13.008 DEBUG_RESOLVER Resolving 127.0.0.1 (PTR "1.0.0.127.in-addr.arpa"): 0 = "localhost"
2024-05-26 02:49:13.008 DEBUG_RESOLVER Client 127.0.0.1 -> "localhost" is new
2024-05-26 02:49:13.008 DEBUG_RESOLVER 1 / 2 client host names resolved
2024-05-26 02:49:13.008 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716953 seconds
2024-05-26 02:49:13.008 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716953 seconds
2024-05-26 02:49:13.008 DEBUG_RESOLVER 2 / 2 upstream server host names resolved
2024-05-26 02:49:32.781 DEBUG_RESOLVER  ---> not found
2024-05-26 02:49:32.783 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "fd71:2002:f23:0:80fd:875a:d51a:40dd"
2024-05-26 02:49:33.028 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it is not new
2024-05-26 02:49:33.028 DEBUG_RESOLVER Skipping client 127.0.0.1 (localhost) because it is not new
2024-05-26 02:49:33.028 DEBUG_RESOLVER Trying to resolve fd71:2002:f23:0:80fd:875a:d51a:40dd
2024-05-26 02:49:33.034 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "127.0.0.1"
2024-05-26 02:49:33.040 DEBUG_RESOLVER  ---> not found
2024-05-26 02:49:33.041 DEBUG_RESOLVER Client fd71:2002:f23:0:80fd:875a:d51a:40dd -> "" is new
2024-05-26 02:49:33.041 DEBUG_RESOLVER 1 / 3 client host names resolved
2024-05-26 02:49:33.041 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716973 seconds
2024-05-26 02:49:33.041 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716973 seconds
2024-05-26 02:49:33.041 DEBUG_RESOLVER 2 / 2 upstream server host names resolved
2024-05-26 02:49:33.616 DEBUG_RESOLVER  ---> not found
2024-05-26 02:49:33.618 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "192.168.2.102"
2024-05-26 02:49:34.042 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it is not new
2024-05-26 02:49:34.042 DEBUG_RESOLVER Skipping client 127.0.0.1 (localhost) because it is not new
2024-05-26 02:49:34.042 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:80fd:875a:d51a:40dd () because it is not new
2024-05-26 02:49:34.042 DEBUG_RESOLVER Trying to resolve 192.168.2.102
2024-05-26 02:49:34.045 DEBUG_RESOLVER Resolving 192.168.2.102 (PTR "102.2.168.192.in-addr.arpa"): 0 = "XXXXXXX.lan"
2024-05-26 02:49:34.045 DEBUG_RESOLVER Client 192.168.2.102 -> "XXXXXXX.lan" is new
2024-05-26 02:49:34.045 DEBUG_RESOLVER 1 / 4 client host names resolved
2024-05-26 02:49:34.045 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716974 seconds
2024-05-26 02:49:34.045 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716974 seconds
2024-05-26 02:49:34.045 DEBUG_RESOLVER 2 / 2 upstream server host names resolved
2024-05-26 02:50:19.276 DEBUG_RESOLVER  ---> not found
2024-05-26 02:50:19.277 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "2601:204:0:cf3c:d748:7533:35fe:55e8"
2024-05-26 02:50:20.089 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it is not new
2024-05-26 02:50:20.089 DEBUG_RESOLVER Skipping client 127.0.0.1 (localhost) because it is not new
2024-05-26 02:50:20.089 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:80fd:875a:d51a:40dd () because it is not new
2024-05-26 02:50:20.089 DEBUG_RESOLVER Skipping client 192.168.2.102 (XXXXXXX.lan) because it is not new
2024-05-26 02:50:20.089 DEBUG_RESOLVER Trying to resolve 2601:204:0:cf3c:d748:7533:35fe:55e8
2024-05-26 02:51:35.499 DEBUG_RESOLVER  ---> not found
2024-05-26 02:51:35.501 DEBUG_RESOLVER getIfaceFromIP(): "SELECT interface FROM network JOIN network_addresses ON network_addresses.network_id = network.id WHERE network_addresses.ip = ? AND interface != 'N/A' AND interface IS NOT NULL;" with ? = "192.168.2.212"

pihole.log

May 26 02:48:32 dnsmasq[165]: query[PTR] 2.0.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa from 127.0.0.1
May 26 02:48:32 dnsmasq[165]: forwarded 2.0.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa to 172.18.0.143#5053
May 26 02:48:32 dnsmasq[165]: reply fd71:2002:f23::102 is NXDOMAIN
May 26 02:48:33 dnsmasq[165]: query[PTR] 1.0.0.127.in-addr.arpa from 127.0.0.1
May 26 02:48:33 dnsmasq[165]: /etc/hosts 127.0.0.1 is localhost
May 26 02:48:48 dnsmasq[165]: query[A] pi.hole from 127.0.0.1
May 26 02:48:48 dnsmasq[165]: Pi-hole hostname pi.hole is 127.0.0.1
May 26 02:49:13 dnsmasq[165]: query[PTR] 1.0.0.127.in-addr.arpa from 127.0.0.1
May 26 02:49:13 dnsmasq[165]: /etc/hosts 127.0.0.1 is localhost
May 26 02:49:18 dnsmasq[165]: query[A] pi.hole from 127.0.0.1
May 26 02:49:18 dnsmasq[165]: Pi-hole hostname pi.hole is 127.0.0.1
--
May 26 02:49:33 dnsmasq[165]: query[PTR] d.d.0.4.a.1.5.d.a.5.7.8.d.f.0.8.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa from 127.0.0.1
May 26 02:49:33 dnsmasq[165]: forwarded d.d.0.4.a.1.5.d.a.5.7.8.d.f.0.8.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa to 172.18.0.143#5053
May 26 02:49:33 dnsmasq[165]: reply fd71:2002:f23:0:80fd:875a:d51a:40dd is NXDOMAIN
May 26 02:49:33 dnsmasq[165]: query[A] i.ytimg.com from 2601:204:0:cf3c::1
--
May 26 02:49:34 dnsmasq[165]: query[PTR] 102.2.168.192.in-addr.arpa from 127.0.0.1
May 26 02:49:34 dnsmasq[165]: forwarded 102.2.168.192.in-addr.arpa to 172.18.0.143#5053
May 26 02:49:34 dnsmasq[165]: reply 192.168.2.102 is XXXXXXXX.lan
May 26 02:49:48 dnsmasq[165]: query[A] pi.hole from 127.0.0.1
--
May 26 02:50:20 dnsmasq[165]: query[PTR] 8.e.5.5.e.f.5.3.3.3.5.7.8.4.7.d.c.3.f.c.0.0.0.0.4.0.2.0.1.0.6.2.ip6.arpa from 127.0.0.1
May 26 02:50:20 dnsmasq[165]: forwarded 8.e.5.5.e.f.5.3.3.3.5.7.8.4.7.d.c.3.f.c.0.0.0.0.4.0.2.0.1.0.6.2.ip6.arpa to 172.18.0.143#5053
May 26 02:50:20 dnsmasq[165]: query[A] github.com from 2601:204:0:cf3c::1
May 26 02:50:20 dnsmasq[165]: forwarded github.com to 172.18.0.143#5053

Going to sleep now.

DL6ER commented 1 month ago

This looks like expected, after your cleaning of queries, you start with an empty database:

2024-05-26 02:48:29.951 INFO Imported 0 queries from the on-disk database (it has 0 rows)
2024-05-26 02:48:29.951 INFO Parsing queries in database
2024-05-26 02:48:29.951 INFO Imported 0 queries from the long-term database

Hence, no clients are known and no initial resolving is happening. As soon as the first query arrives, the corresponding client is resolved

2024-05-26 02:48:32.953 DEBUG_RESOLVER Trying to resolve fd71:2002:f23::102
2024-05-26 02:48:32.958 DEBUG_RESOLVER  ---> not found
2024-05-26 02:48:32.966 DEBUG_RESOLVER Client fd71:2002:f23::102 -> "" is new
2024-05-26 02:48:32.966 DEBUG_RESOLVER 1 / 1 client host names resolved

which works as expected

May 26 02:48:32 dnsmasq[165]: query[PTR] 2.0.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa from 127.0.0.1
May 26 02:48:32 dnsmasq[165]: forwarded 2.0.1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.3.2.f.0.2.0.0.2.1.7.d.f.ip6.arpa to 172.18.0.143#5053
May 26 02:48:32 dnsmasq[165]: reply fd71:2002:f23::102 is NXDOMAIN
2024-05-26 02:48:32.967 DEBUG_RESOLVER Skipping upstream 172.18.0.143 () because it was inactive for 1716716912 seconds
2024-05-26 02:48:32.967 DEBUG_RESOLVER Skipping upstream fd01::11 () because it was inactive for 1716716912 seconds

This is a bug and fixed by https://github.com/pi-hole/FTL/commit/2843fb0203d9aa973ea16e5a78f5d1eddf0c87c4. The requirement for this bug to be triggered is starting FTL on an empty database - it won't appear in "normal" cases.

The following name resolving is working as expected:

2024-05-26 02:48:33.968 DEBUG_RESOLVER Trying to resolve 127.0.0.1
2024-05-26 02:48:33.969 DEBUG_RESOLVER Resolving 127.0.0.1 (PTR "1.0.0.127.in-addr.arpa"): 0 = "localhost"
2024-05-26 02:48:33.970 DEBUG_RESOLVER Client 127.0.0.1 -> "localhost" is new

Your log snippet above shows only five clients:

None of these are unexpected results and everything seems to work up until here?

Plus the two upstream servers which should work fine as of the fix.

Please run

pihole checkout ftl fix/resolver

in about 5 minutes from me posting this comment to get a customized FTL variant we can work on for fixing what we find here. For one it makes debug.resolver become much more verbose so we can be sure if DNS question and answer have been processed as expected. Also it fixes the issue you have found with the non-resolving upstreams when starting from an empty database.

moya2162 commented 1 month ago

Running command pihole checkout ftl fix/resolver within container yields Function not supported in Docker images

Do I need to follow instructions here and here instead?

DL6ER commented 1 month ago

Oh yes, sorry - I always forget about this docker specialty. @PromoFaux maybe either of us remembers to at least put the link to the README there before we release v6.

But I think we should also re-enable this at least for checkout ftl printing a bold warning that this change is only temporarily and non-persistent in docker.

PromoFaux commented 1 month ago

Off the top of my head checkout commands effectively utilise the install script, none of which is actually utilised in the docker image.

The build script in the docker repo should suffice, but perhaps we can add in a link to the instructions to the checkout command

moya2162 commented 1 month ago

Rebuilt docker image, deleted all configs and let pihole rebuild from scratch. Made only following modifications:

FTLCONF_dns_upstreams='unbound#5053'
FTLCONF_dns_listeningMode=all
FLTCONF_dns_bogusPriv='false'
FTLCONF_debug_resolver='true'
pihole -v
Core
    Version is 8a92486 (Latest: null)
    Branch is development-v6
    Hash is 8a924867 (Latest: N/A)
Web
    Version is 59b1dcf (Latest: null)
    Branch is development-v6
    Hash is 59b1dcfc (Latest: N/A)
FTL
    Version is vDev-2843fb0 (Latest: null)
    Branch is fix/resolver
    Hash is 2843fb02 (Latest: N/A)

My FTL logs still look the same as previous.

EDIT 1 ---------------

Saw a new commit under fix/resolver, rebuilt image, now im seeing following in FTL.log:

FTL
    Version is vDev-5db4ade (Latest: null)
    Branch is fix/resolver
    Hash is 5db4ade0 (Latest: N/A)
2024-05-26 14:16:11.322 DEBUG_RESOLVER Trying to resolve 192.168.2.53
2024-05-26 14:16:11.322 DEBUG_RESOLVER Resolving PTR "53.2.168.192.in-addr.arpa" on 127.0.0.1#53 (TCP)
2024-05-26 14:16:11.322 ERROR Cannot send TCP DNS query: Broken pipe
2024-05-26 14:16:11.322 DEBUG_RESOLVER Trying to obtain host name of "192.168.2.53" from network_addresses table
2024-05-26 14:16:11.324 DEBUG_RESOLVER  ---> not found
2024-05-26 14:16:11.325 DEBUG_RESOLVER Client 192.168.2.53 -> "" is new
...
2024-05-26 14:52:21.477 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:a9d9:6db1:ff01:d5f6 () because it is not new
2024-05-26 14:52:21.477 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c::102 () because it is not new
2024-05-26 14:52:21.478 DEBUG_RESOLVER Skipping client 127.0.0.1 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client fd71:2002:f23::102 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.53 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:1f3:52aa:cb48:8210 () because it is not new
2024-05-26 14:52:21.479 DEBUG_ANY Reopening Gravity database for this fork
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.101 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.43 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.21 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:b1f6:ea45:cc01:eae8 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.60 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:453b:ee24:f6fa:6d01 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:2187:6b29:9fa4:9349 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:610c:2dbd:4b87:cef3 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client fd71:2002:f23:0:2187:6b29:9fa4:9349 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:453b:ee24:f6fa:6d01 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.40 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.102 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 192.168.2.212 () because it is not new
2024-05-26 14:52:21.479 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:d748:7533:35fe:55e8 () because it is not new
2024-05-26 14:52:21.480 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c:610c:2dbd:4b87:cef3 () because it is not new
2024-05-26 14:52:21.480 DEBUG_RESOLVER Skipping client 192.168.2.34 () because it is not new
2024-05-26 14:52:21.480 DEBUG_RESOLVER Skipping client 2601:204:0:cf3c::41 () because it is not new
2024-05-26 14:52:21.480 DEBUG_RESOLVER Skipping client fd71:2002:f23::41 () because it is not new
2024-05-26 14:52:21.480 DEBUG_RESOLVER Skipping client 192.168.2.41 () because it is not new
2024-05-26 14:52:21.509 DEBUG_RESOLVER 1 / 26 client host names resolved
2024-05-26 14:52:21.509 DEBUG_RESOLVER Upstream 172.18.0.143 -> "" already known
2024-05-26 14:52:21.509 DEBUG_RESOLVER Upstream fd01::11 -> "" already known
2024-05-26 14:52:21.509 DEBUG_RESOLVER 0 / 2 upstream server host names resolved

Also this error under diagnosis:

Connection error (172.18.0.143#5053): failed to send TCP(read_write) packet (Connection prematurely closed by remote server)

EDIT 2 ---------------

Ok at top of the hour FTL.log just grabbed this (only pasted example for a few of my clients):

2024-05-26 15:00:01.015 DEBUG_RESOLVER Trying to resolve 192.168.2.101
2024-05-26 15:00:01.015 DEBUG_RESOLVER Resolving PTR "101.2.168.192.in-addr.arpa" on 127.0.0.1#53 (TCP)
2024-05-26 15:00:01.058 DEBUG_RESOLVER DNS query for PTR "101.2.168.192.in-addr.arpa" returned status NXDomain (Non-Existent Domain) (3)
2024-05-26 15:00:01.058 DEBUG_RESOLVER Trying to obtain host name of "192.168.2.101" from network_addresses table
2024-05-26 15:00:01.060 DEBUG_RESOLVER  ---> not found
2024-05-26 15:00:01.061 DEBUG_RESOLVER Client 192.168.2.101 -> "" is new
2024-05-26 15:00:01.061 DEBUG_RESOLVER Trying to resolve 192.168.2.43
2024-05-26 15:00:01.061 DEBUG_RESOLVER Resolving PTR "43.2.168.192.in-addr.arpa" on 127.0.0.1#53 (TCP)
2024-05-26 15:00:01.106 DEBUG_RESOLVER DNS query for PTR "43.2.168.192.in-addr.arpa" returned status NXDomain (Non-Existent Domain) (3)
2024-05-26 15:00:01.106 DEBUG_RESOLVER Trying to obtain host name of "192.168.2.43" from network_addresses table
2024-05-26 15:00:01.108 DEBUG_RESOLVER  ---> not found
2024-05-26 15:00:01.108 DEBUG_RESOLVER Client 192.168.2.43 -> "" is new

pihole.log filtered for PTR:

May 26 15:00:01 dnsmasq[1079]: query[PTR] 101.2.168.192.in-addr.arpa from 127.0.0.1
May 26 15:00:01 dnsmasq[1079]: config 192.168.2.101 is NXDOMAIN
May 26 15:00:01 dnsmasq[1079]: query[PTR] 43.2.168.192.in-addr.arpa from 127.0.0.1
May 26 15:00:01 dnsmasq[1079]: config 192.168.2.43 is NXDOMAIN

It appears PTR requests are being forwarded to localhost and not upstream resolver.

rdwebdesign commented 1 month ago

As a test, try to use the host IP in FTLCONF_dns_upstreams:

FTLCONF_dns_upstreams='<host_IP>#5053'

Do you see any change?

moya2162 commented 1 month ago

Hardcoded upstream dns and added also tried setting pihole conditional forward to my unbound container's IP and port, still looks like PTR is forwarded to 127.0.0.1 rather than upstream DNS.

nslookupalso appears broken when executed from my client computer, results in NXDOMAIN.

rdwebdesign commented 1 month ago

Please post the full nslookup command and output, running from your client.

moya2162 commented 1 month ago

nslookupcommand and output

C:\Users\<CLIENT>> nslookup 192.168.2.30 192.168.2.102
Server:  UnKnown
Address:  192.168.2.102

*** UnKnown can't find 192.168.2.30: Non-existent domain

This exact command was working before and now its not. PTR is now being forwarded to 127.0.0.1 instead of upstream dns.

If i bypass Pihole and go directly to my router which maintains my hostnames it works

C:\Users\<CLIENT>> nslookup 192.168.2.30 192.168.2.1
Server:  <ROUTER>.lan
Address:  192.168.2.1

Name:    <CLIENT>.lan
Address:  192.168.2.30

EDIT -------------

@DL6ER Appears hourly PTR requests are now being produced by Pihole, however PTR requests are now being forwarded to 127.0.0.1instead of upstream. Makese sense based on the edits in the commit.

DL6ER commented 1 month ago

The hourly requests have always been sent to 127.0.0.1, the only thing this commit does is changing from UDP to TCP as I've seen some truncation for very large replies (involving DNSSEC). The flow should be FTL sending them to itself and then they should be handled and sent upstream.

I've just seen your edits.

2024-05-26 14:16:11.322 ERROR Cannot send TCP DNS query: Broken pipe

This is unfortunate, so it seems we indeed need to implement reconnecting. Or we need to find a way how to signal to try again later.

May 26 15:00:01 dnsmasq[1079]: config 192.168.2.101 is NXDOMAIN

This is the problem and the real reason for

This exact command was working before and now its not.

Everything looks like

FLTCONF_dns_bogusPriv='false'

doesn't work. Could you please check the /etc/pihole/dnsmasq.conf whether bogus-priv is really absent from this file?

moya2162 commented 1 month ago

Yes you are right. Had a typo in my compose file and the variable bogusPriv was not being set. Upon correction I am seeing PTR requests and resolutions upstream for my clients. Im not entirely convinced its 100% reliable but so far its working as I expect it. I need more long term logs to verify.

I saw your new commit and refreshed my image:

FTL
    Version is vDev-090c1ad (Latest: null)
    Branch is fix/resolver
    Hash is 090c1ada (Latest: 090c1ada)

I am sill receiving the following error in Piholes, but its not super frequent:

Connection error (172.18.0.143#5053): failed to send TCP(read_write) packet (Connection prematurely closed by remote server)

Something i've noticed and want to mention but may not be in scope of this issue. Let me know if i should make a new issue to track. I downloaded and opened pihole-FTL.db to see how the network tables were set up and I am noticing that only ipv4 address have a hostname assigned to them in network_addresses. Now with resolver.refreshNames=IPV4_ONLY that makes sense. However with resolver.networkNames=true i would think that once Pihole has used client MAC address to identify ipv4 and ipv6 addresses to the same device, it should loop back and update the hostname for the ipv6 client within the database.

Screenshot 2024-05-27 095552

If this was done, then when filtering queries it would be easy to isolate a single device on the network with 'Client (by name)' and if futher filtering was need it could be done by other filters.

DL6ER commented 1 month ago

Yeah, it's better to create a separate issue ticket to avoid confusion/mixing unrelated stuff and then forgetting about something in the end.

Okay, so fix/resolver fixed this for you or has the typo always been there and it may not even be broken in development-v6? This is unclear to me, so far. But I guess the typo is new.

Connection error (172.18.0.143#5053): failed to send TCP(read_write) packet (Connection prematurely closed by remote server)

Well, this may be an issue with unbound - you will probably have to enable verbose logging in unbound to find the reason. I don't think it should disturb DNS resolution but pihole.log at the time of the error will have more details.

moya2162 commented 1 month ago

Understood. Will make a new issue ticket. Would you recommend under pihole or FTL?

Yah that typo on my end. In the beginning i was setting bogusPriv via the interface then half way through i switched to using environment variables in docker. You can see my typo in my post above. Just to make sure i rolled back to development-v6 and with debug.resolver=true and dns.bogusPriv=false and i dont see any PTR requests being generated by Pihole in the queries log.

Changed back to fix/resolver, 090c1ada and so far i would say fix/resolver appears to be working. Hostsnames are getting assigned.

I will dig into unbound logs to see if connection issue is there.

DL6ER commented 1 month ago

Sorry, I didn't see your comment. The improvements have been merged into development-v6 and I'd recommend you get back on track as soon as possible. The branch fix/resolver will not receive any future updates. Thanks for testing and I'll try to allocate some time for checking your other issue soon.