Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Restart DNS resolver" required every few days to make browsing work again! #5608

Closed
sts-ryan-holton opened this issue Mar 16, 2024 · 42 comments

Comments

@sts-ryan-holton
Copy link

Versions

Pi-hole version is v5.17.3 (Latest: v5.17.3)
web version is v5.21 (Latest: v5.21)
FTL version is v5.25.1 (Latest: v5.25.1)

Platform

  • OS and version: Pihole
  • Platform: Raspberry Pi

Expected behavior

I shouldn't be required to restart DNS resolver all of the time

Actual behavior / bug

Hi 👋

I'm not completely sure whether here is the best place to put this but hope it gets some response. I've been running PiHole on my Raspberry Pi 4 4GB model for a few years now, always had the latest version of Pi Hole.

I've indentified some common issues that I can remedy by restarting DNS resolver, and also by rebooting the Pi (I've considered a timer)

Essentially, every few days when browsing the internet on devices the internet connection will appear to hang, the actual router and Pi both have a connection, it seems that clicking the "Restart DNS resolver" button will solve it temporarily and then I'll need to click it after a few more random days, and have done for months now.

In addition, it seems the Pi Hole just occassionally locks up entirely leading me to restarting the Pi, this solves 9/10 problems.

I'm just wondering, is the DNS resolver settings automatically restarting and i can change it's frequency, and also any tips for faster loading of pages

@lionslair
Copy link

I have been experiencing the same thing but it appears to be weekly on Sunday morning. I am running on a HP micro server. I have a number of Docker containers plus MySQL nginz etc and other services.

Pihole in installed natively not virtualised. I have a second pihole on a pi4 as redundancy.

However seems only the main pihole is being used and other devices such as desktop is unable to resolve 90% on domain until I do a server reboot.

Haven't been able to pinpoint the cause but after a full server reboot all just works again.

@crycode-de
Copy link

Same for me running Pi-hole in a Proxmox LXC.
Round about every 7 days the DNS and DHCP responses will become really slow.
If this happens, the RAM usage of the LXC is increased rapidly by nearly factor 2 (normally ~55Mb, in this case >100Mb).

After an LXC restart, everything is working fine for the next 7 days.

grafik

Pi-hole version is v5.17.3 (Latest: v5.17.3)
web version is v5.21 (Latest: v5.21)
FTL version is v5.25.1 (Latest: v5.25.1)

@sts-ryan-holton
Copy link
Author

@lionslair I thought I was the only one experiencing this! 💪

If it's worth knowing, some 20 hours since posting the question and restarting DNS resolver:

  • Total CPU utilization: 1.3%
  • Memory utilization: 1.4%
  • Used memory: 13.57 MB
  • DNS cache size: 10,000
  • DNS cache insertions:: 7,683
  • DNS cache evictions: 0

@lionslair
Copy link

I will have to note stats next week

@sts-ryan-holton
Copy link
Author

My Pi became unresponsive this evening, had to reboot.

@crycode-de
Copy link

Happened again today but this time the pihole-FTL service crashed and was restarted by systemd.

RAM usage was at ~60MB until ~03:30 UTC, then jumped to 215MB at ~05:00 UTC.
At 06:16 UTC the pihole-FTL service crashed and was restarted. RAM usage was normal again.

grafik

grafik

(Times in screenshots are in UTC+1)

Relevant log entries from journal:

Mar 22 06:16:17 pi-hole systemd[1]: pihole-FTL.service: Main process exited, code=exited, status=1/FAILURE
Mar 22 06:16:17 pi-hole systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Mar 22 06:16:17 pi-hole systemd[1]: pihole-FTL.service: Consumed 13min 4.869s CPU time.

Mar 22 06:16:22 pi-hole systemd[1]: pihole-FTL.service: Scheduled restart job, restart counter is at 1.
Mar 22 06:16:22 pi-hole systemd[1]: Stopped pihole-FTL.service - Pi-hole FTL.
Mar 22 06:16:22 pi-hole systemd[1]: pihole-FTL.service: Consumed 13min 4.869s CPU time.
Mar 22 06:16:22 pi-hole systemd[1]: Starting pihole-FTL.service - Pi-hole FTL...
Mar 22 06:16:22 pi-hole systemd[1]: Started pihole-FTL.service - Pi-hole FTL.
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] Using log file /var/log/pihole/FTL.log
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] ########## FTL started on pi-hole! ##########
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] FTL branch: master
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] FTL version: v5.25.1
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] FTL commit: 1c2257be
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] FTL date: 2024-02-20 20:02:36 +0100
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] FTL user: pihole
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] Compiled for x86_64 (compiled on CI) using gcc (Debian 8.3.0-6) 8.3.0
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    SOCKET_LISTENING: only local
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    AAAA_QUERY_ANALYSIS: Show AAAA queries
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    MAXDBDAYS: max age for stored queries is 365 days
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    RESOLVE_IPV6: Resolve IPv6 addresses
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    RESOLVE_IPV4: Resolve IPv4 addresses
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    DBINTERVAL: saving to DB file every minute
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    DBFILE: Using /etc/pihole/pihole-FTL.db
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.959 48378M]    MAXLOGAGE: Importing up to 24.0 hours of log data
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    PRIVACYLEVEL: Set to 0
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    IGNORE_LOCALHOST: Show queries from localhost
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCKINGMODE: Null IPs for blocked domains
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    DBIMPORT: Importing history from database
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    PIDFILE: Using /run/pihole-FTL.pid
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    SOCKETFILE: Using /run/pihole/FTL.sock
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    MACVENDORDB: Using /etc/pihole/macvendor.db
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    GRAVITYDB: Using /etc/pihole/gravity.db
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    PARSE_ARP_CACHE: Active
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    CNAME_DEEP_INSPECT: Active
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    DELAY_STARTUP: No delay requested.
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    NICE: Cannot change niceness to -10 (permission denied)
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    MAXNETAGE: Removing IP addresses and host names from network table after 365 days
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    NAMES_FROM_NETDB: Enabled, trying to get names from network database
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    EDNS0_ECS: Overwrite client from ECS information
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    REFRESH_HOSTNAMES: Periodically refreshing IPv4 names
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    RATE_LIMIT: Rate-limiting client making more than 1000 queries in 60 seconds
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    LOCAL_IPV4: Automatic interface-dependent detection of address
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    LOCAL_IPV6: Automatic interface-dependent detection of address
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCK_IPV4: Automatic interface-dependent detection of address
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCK_IPV6: Automatic interface-dependent detection of address
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    SHOW_DNSSEC: Enabled, showing automatically generated DNSSEC queries
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    MOZILLA_CANARY: Enabled
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    PIHOLE_PTR: internal PTR generation enabled (pi.hole)
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    ADDR2LINE: Enabled
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    REPLY_WHEN_BUSY: Drop queries when the database is busy
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCK_TTL: 2 seconds
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    BLOCK_ICLOUD_PR: Enabled
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    CHECK_LOAD: Enabled
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    CHECK_SHMEM: Warning if shared-memory usage exceeds 90%
Mar 22 06:16:22 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M]    CHECK_DISK: Warning if certain disk usage exceeds 90%
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M] Finished config file parsing
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M] Creating mutex
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.961 48378M] Creating mutex
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.962 48378M] PID of FTL process: 48378
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.965 48378M] Database version is 12
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.965 48378M] Resizing "FTL-strings" from 40960 to (81920 * 1) == 81920 (/dev/shm: 712.7KB used, 8.3GB total, FTL uses 700.8KB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.965 48378M] Imported 0 alias-clients
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.966 48378M] Database successfully initialized
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:22.974 48378M] New upstream server: 1.1.1.1:53 (0/512)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.007 48378M] New upstream server: 1.0.0.1:53 (1/512)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.022 48378M] Resizing "FTL-queries" from 229376 to (8192 * 56) == 458752 (/dev/shm: 753.7KB used, 8.3GB total, FTL uses 741.7KB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.046 48378M] Resizing "FTL-queries" from 458752 to (12288 * 56) == 688128 (/dev/shm: 983.0KB used, 8.3GB total, FTL uses 971.1KB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.046 48378M] Resizing "FTL-domains" from 12288 to (1024 * 24) == 24576 (/dev/shm: 1.2MB used, 8.3GB total, FTL uses 1.2MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.064 48378M] New upstream server: 172.30.2.10:53 (2/512)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.067 48378M] Resizing "FTL-queries" from 688128 to (16384 * 56) == 917504 (/dev/shm: 1.2MB used, 8.3GB total, FTL uses 1.2MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.083 48378M] Resizing "FTL-queries" from 917504 to (20480 * 56) == 1146880 (/dev/shm: 1.5MB used, 8.3GB total, FTL uses 1.4MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.100 48378M] Resizing "FTL-queries" from 1146880 to (24576 * 56) == 1376256 (/dev/shm: 1.7MB used, 8.3GB total, FTL uses 1.7MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.123 48378M] Resizing "FTL-queries" from 1376256 to (28672 * 56) == 1605632 (/dev/shm: 1.9MB used, 8.3GB total, FTL uses 1.9MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.139 48378M] Resizing "FTL-queries" from 1605632 to (32768 * 56) == 1835008 (/dev/shm: 2.1MB used, 8.3GB total, FTL uses 2.1MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.155 48378M] Resizing "FTL-queries" from 1835008 to (36864 * 56) == 2064384 (/dev/shm: 2.4MB used, 8.3GB total, FTL uses 2.4MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.170 48378M] Resizing "FTL-queries" from 2064384 to (40960 * 56) == 2293760 (/dev/shm: 2.6MB used, 8.3GB total, FTL uses 2.6MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.188 48378M] Resizing "FTL-queries" from 2293760 to (45056 * 56) == 2523136 (/dev/shm: 2.8MB used, 8.3GB total, FTL uses 2.8MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.201 48378M] Resizing "FTL-queries" from 2523136 to (49152 * 56) == 2752512 (/dev/shm: 3.1MB used, 8.3GB total, FTL uses 3.0MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.207 48378M] Resizing "FTL-domains" from 24576 to (1536 * 24) == 36864 (/dev/shm: 3.3MB used, 8.3GB total, FTL uses 3.3MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.217 48378M] Resizing "FTL-queries" from 2752512 to (53248 * 56) == 2981888 (/dev/shm: 3.3MB used, 8.3GB total, FTL uses 3.3MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.242 48378M] Resizing "FTL-queries" from 2981888 to (57344 * 56) == 3211264 (/dev/shm: 3.5MB used, 8.3GB total, FTL uses 3.5MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.265 48378M] Resizing "FTL-queries" from 3211264 to (61440 * 56) == 3440640 (/dev/shm: 3.8MB used, 8.3GB total, FTL uses 3.7MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.288 48378M] Resizing "FTL-queries" from 3440640 to (65536 * 56) == 3670016 (/dev/shm: 4.0MB used, 8.3GB total, FTL uses 4.0MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.302 48378M] Resizing "FTL-queries" from 3670016 to (69632 * 56) == 3899392 (/dev/shm: 4.2MB used, 8.3GB total, FTL uses 4.2MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.325 48378M] Resizing "FTL-queries" from 3899392 to (73728 * 56) == 4128768 (/dev/shm: 4.4MB used, 8.3GB total, FTL uses 4.4MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.342 48378M] Resizing "FTL-queries" from 4128768 to (77824 * 56) == 4358144 (/dev/shm: 4.7MB used, 8.3GB total, FTL uses 4.7MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.358 48378M] Resizing "FTL-queries" from 4358144 to (81920 * 56) == 4587520 (/dev/shm: 4.9MB used, 8.3GB total, FTL uses 4.9MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.384 48378M] Resizing "FTL-queries" from 4587520 to (86016 * 56) == 4816896 (/dev/shm: 5.1MB used, 8.3GB total, FTL uses 5.1MB)
Mar 22 06:16:23 pi-hole pihole-FTL[48378]: [2024-03-22 06:16:23.405 48378M] Resizing "FTL-queries" from 4816896 to (90112 * 56) == 5046272 (/dev/shm: 5.4MB used, 8.3G

@lionslair
Copy link

Happened again today. Started from midnight.

No real issues again. Only thing in the log I could see was

Notice: Database size is 2471.66 MB

Since I have two running I do not know why its not falling over to the second IP. My guess is the first is answering it but not responding. Really confusing it does not seem to be all.

Also had log records of

ipv6 no reply

I don't know what started this or what the issue is but it is weekly on Sunday it occurs.

@lionslair
Copy link

Happened again today. Started from midnight.

No real issues again. Only thing in the log I could see was

Notice: Database size is 2471.66 MB

Since I have two running I do not know why its not falling over to the second IP. My guess is the first is answering it but not responding. Really confusing it does not seem to be all.

Also had log records of

ipv6 no reply

I don't know what started this or what the issue is but it is weekly on Sunday it occurs. Gone through all logs and nothing seems off.

@lionslair
Copy link

starting to think somehow it might be connected to my tailscale / headscale install messing something up

@sts-ryan-holton
Copy link
Author

Hopefully a project contributor sees this soon as an issue 👀

@DL6ER
Copy link
Member

DL6ER commented Mar 24, 2024

Sorry for not picking this earlier, family life (outside the computer) is quite busy for me these days :-) Let's see if I can extract the key points that have been made herein so far:

If this happens, the RAM usage of the LXC is increased rapidly by nearly factor 2

This is not unexpected and rather indicates that Pi-hole is indeed still working. The most likely cause IMO for the rapid increase in memory needs: mere fact that no name resolution was running caused all the clients in your network to retry their queries quite often. As Pi-hole stores all queries in memory to have them available at an instant for the Query Log - this increase is expected.

Happened again today but this time the pihole-FTL service crashed and was restarted by systemd.

The log excerpt you posted contains no details about a crash, the only pointer to might might be:

Mar 22 06:16:17 pi-hole systemd[1]: pihole-FTL.service: Main process exited, code=exited, status=1/FAILURE
Mar 22 06:16:17 pi-hole systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.

but this can have easily caused by something not a crash. Please review the files in your /var/log/pihole/FTL.log.* (with emphasis on the rotated files that should the in there as well) to find what really happened at that time. Is there any SHM size limitation on your system?


Overall, to all of you: Please check your /var/log/pihole/pihole.log at/around/after the time the incident happens. It should show us if (a) Pi-hole stops receiving queries, (b) receives them but doesn't forward them upstream, (c) receives, processes and forwards them but never receives a response, or (d) something else.

@crycode-de
Copy link

@DL6ER Thank you for your response.

The RAM usage only increases that much when the DNS gets really slow/unresponsive.


From the FTL.log.*:

[2024-03-22 03:57:02.100 166/T287] Error while trying to close database: database is locked
[2024-03-22 03:57:03.122 166/T287] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2024-03-22 03:57:03.122 166/T287] WARNING: Storing devices in network table failed: database is locked
[2024-03-22 03:58:01.030 166/T287] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2024-03-22 03:58:01.030 166/T287] END TRANSACTION failed when trying to store queries to long-term database
[2024-03-22 03:58:01.030 166/T287] Keeping queries in memory for later new attempt
[2024-03-22 03:58:02.054 166/T287] ERROR: SQL query "END TRANSACTION" failed: database is locked (SQLITE_BUSY)
[2024-03-22 03:58:02.054 166/T287] WARNING: Storing devices in network table failed: database is locked

At this time the increased RAM usage also starts. Probably cause of "Keeping queries in memory for later new attempt".

From then on there are multiple messages like

[2024-03-22 03:58:18.448 166M] WARNING in dnsmasq core: not giving name repeater1.home to the DHCP lease of fd00::3091:abff:fe19:6a00 because the name exists in /etc/pihole/custom.list with address fe80::3091:abff:fe19:6a00
[2024-03-22 03:58:19.449 166M] add_message(type=5, message=not giving name repeater1.home to the DHCP lease of fd00::3091:abff:fe19:6a00 because the name exists in /etc/pihole/custom.list with address fe80::3091:abff:fe19:6a00) - SQL error step DELETE: database is locked
[2024-03-22 03:58:19.449 166M] Error while trying to close database: database is locked

Always for the same devices. I've defined local DNS records for most of my devices to the IPv4 and fe80 IPv6 of the devices. The warning messages above are only logged for some of my devices.

Later the log stops at 04:46 and the restart at 06:16 is logged:

[2024-03-22 04:46:50.549 166M] Error while trying to close database: database is locked
[2024-03-22 06:16:22.959 48378M] Using log file /var/log/pihole/FTL.log
[2024-03-22 06:16:22.959 48378M] ########## FTL started on pi-hole! ##########
[2024-03-22 06:16:22.959 48378M] FTL branch: master
[2024-03-22 06:16:22.959 48378M] FTL version: v5.25.1
[2024-03-22 06:16:22.959 48378M] FTL commit: 1c2257be
[2024-03-22 06:16:22.959 48378M] FTL date: 2024-02-20 20:02:36 +0100
[2024-03-22 06:16:22.959 48378M] FTL user: pihole
[2024-03-22 06:16:22.959 48378M] Compiled for x86_64 (compiled on CI) using gcc (Debian 8.3.0-6) 8.3.0
[2024-03-22 06:16:22.959 48378M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)

From pihole.log.*:
Since 04:47 until the restart for most queries the following is logged:

Mar 22 04:47:14 dnsmasq[166]: query[A] chat.avatar.ext.hp.com from 192.168.1.24
Mar 22 04:47:14 dnsmasq[166]: config error is REFUSED (EDE: network error)

Also some queries seems to be served from cache:

Mar 22 04:48:52 dnsmasq[166]: query[A] api-app.dc-eu.ww.ecouser.net from 192.168.0.102
Mar 22 04:48:52 dnsmasq[166]: cached api-app.dc-eu.ww.ecouser.net is <CNAME>
Mar 22 04:48:52 dnsmasq[166]: cached slb-web-new-ops-eu.dc.ww.ecouser.net is 52.58.74.156

So the queries are received but cannot be handled due to a hanging pihole-FTL service?


SHM size in the LCX is currently 7.8G which should be enough.

root@pi-hole:~# df -h /dev/shm
Filesystem      Size  Used Avail Use% Mounted on
tmpfs           7.8G  8.5M  7.8G   1% /dev/shm

@DL6ER
Copy link
Member

DL6ER commented Mar 24, 2024

So the queries are received but cannot be handled due to a hanging pihole-FTL service?

No, they are processed and the result is:

Mar 22 04:47:14 dnsmasq[166]: config error is REFUSED (EDE: network error)

EDE is "extended DNS error" and "network error" means sending DNS packets (sendto()) failed either here or here. In both cases, this can only happen there is an issue with the upstream connectivity. For this, I need more input from both of you: What is/are your upstream server(s)? Are there multiple?

I heard @lionslair is also using tailscale / headscale, maybe some connection gets lost here. Others are running in some containerized/virtualized environment and maybe something is happening to the network interface here, too.
The fact that it keep being stuck - but restarting the process helps - might suggest a bug in recovering from an intermittent network issue? We're still guessing here, though.

@DL6ER
Copy link
Member

DL6ER commented Mar 24, 2024

I prepared a special FTL version for you to try, it does nothing more than trying to be somewhat more verbose when sending packets failed the way we observe them failing for you. Please run

pihole checkout ftl fix/ede_neterr

and check for new log lines like

failed to send packet: ... some reason ...

once you see this happening the next time.

Important

This special branch is only meant to be used by Pi-hole v5.x users. Do not try to use them if you are currently participating in Pi-hole's public v6 beta.

@bkodenkt
Copy link

bkodenkt commented Mar 24, 2024

Hello everyone, I can confirm this problem on my system and maybe I can contribute by adding my setup information.

Pi-hole [v5.17.3]
FTL [v5.25.1]
Web Interface [v5.21]

It is a Debian 12 "bookworm" VM on a Proxmox server, all packages are up to date on both the guest and the host system.

Problems started on Friday evening, all of a sudden no DNS queries could get resolved anymore. I stopped and restarted "blocking" via the web frontend, since it gave me a red dot and "blocking disabled" on the upper left of the screen. This worked up untill 11:54 am today, at least that's when all of my Proxmox VMs stopped responding and giving load updates to the host system. Unfortunately, I was not able to reach the web frontend today, so I ultimately had to reboot the whole Proxmox server.

I had extensive logging going on the last weeks as I was trying to identify a dodgy iot device that repeatedly kept spamming ntp servers. After finding and eliminating the problem, I switched off logging, flushed the 24h logs, removed some temporary "helper" local DNS entries and deleted the long-term logs manually by doing "rm pihole-FTL.db" after stopping the FTL-service and restarting it afterwards, as described here: https://discourse.pi-hole.net/t/how-to-clear-all-logs-including-long-term-data/39514 This can be a simple coincidence though, as I also recently updated the FTL component from 5.24 to 5.25.1 via pihole -up.

EDIT: I added 5 11 * * * service pihole-FTL restart in root's crontab of the VM as a temporary workaround. Maybe this rather crude approach helps out as long as the culprit is not determined.

EDIT2: I have no upstream DNS servers configured, I use unbound on localhost.

@lionslair
Copy link

Using two servers both ipv4 and IPv6

I think I mentioned I also have a backup instance but requests seem to be using the primary instance. Screenshot_20240324-200629.png

I will try your branch. As I said It happens every Sunday morning for over a month and I really appreciate the feedback and help as I have tried to find it myself but I am missing something. Can not find anything in the log.

Programmer myself so not phased scanning logs and after three hours found nothing today.

Will try the branch thank you.

@lionslair
Copy link

I prepared a special FTL version for you to try, it does nothing more than trying to be somewhat more verbose when sending packets failed the way we observe them failing for you. Please run

pihole checkout ftl fix/ede_neterr

and check for new log lines like

failed to send packet: ... some reason ...

once you see this happening the next time.

[!IMPORTANT]
This special branch is only meant to be used by Pi-hole v5.x users. Do not try to use them if you are currently participating in Pi-hole's public v6 beta.

Getting GitHub error

Screenshot_20240324-201147.png

@crycode-de
Copy link

crycode-de commented Mar 24, 2024

My upstream DNS servers are Cloudflare IPv4:
grafik

I don't think it's related to network errors in my case, since I'm monitoring my network including the online connection and there are no problems logged.

Trying to checkout the test branch also gives me the error fatal: unable to access 'https://github.com/pi-hole/pi-hole/': Could not resolve host: github.com:
grafik

Edit:
pihole -v reports FTL version is fix/ede_neterr vDev-d0f1682 (Latest: v5.25.1), so it seems it worked.

@DL6ER
Copy link
Member

DL6ER commented Mar 24, 2024

Could not resolve host: github.com

Hmm, this should not happen (quite obviously). Can you resolve any names on your Pi-hole? Note that if your Pi-hole is using itself as resolver (nameserver 127.0.0.1 in /etc/resolv.conf), pihole-FTL needs to be running for this to work.

@lionslair
Copy link

Could not resolve host: github.com

Hmm, this should not happen (quite obviously). Can you resolve any names on your Pi-hole? Note that if your Pi-hole is using itself as resolver (nameserver 127.0.0.1 in /etc/resolv.conf), pihole-FTL needs to be running for this to work.

Was on phone but will try again this morning. On same network from phone. It's very odd I have had strange GitHub resolution issues when building Docker and the host connected to tail scale before but that seems to have resolved itself last few months.

@lionslair
Copy link

Ran this

╰─$ pihole checkout ftl fix/ede_neterr
  Please note that changing branches severely alters your Pi-hole subsystems
  Features that work on the master branch, may not on a development branch
  This feature is NOT supported unless a Pi-hole developer explicitly asks!
  Have you read and understood this? [y/N] y

  [✓] Branch fix/ede_neterr exists
  [i] Switching to branch: "fix/ede_neterr" from "fix/ede_neterr"
  [✓] Downloading and Installing FTL
  [✓] Restarting pihole-FTL service...
  [✓] Enabling pihole-FTL service to start on reboot...
fatal: unable to access 'https://github.com/pi-hole/pi-hole/': Could not resolve host: github.com
fatal: unable to access 'https://github.com/pi-hole/web/': Could not resolve host: github.com
fatal: unable to access 'https://github.com/pi-hole/FTL/': Could not resolve host: github.com

but the log has this

ar 25 07:49:54 llserver systemd[1]: pihole-FTL.service: Succeeded.
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.710 1294888M] Using log file /var/log/pihole/FTL.log
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.710 1294888M] ########## FTL started on llserver.lionslair.net.au! ##########
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] FTL branch: fix/ede_neterr
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] FTL version: vDev-d0f1682
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] FTL commit: d0f16824
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] FTL date: 2024-03-24 12:42:49 +0100
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] FTL user: pihole
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] Compiled for x86_64 (compiled on CI) using gcc (Debian 8.3.0-6) 8.3.0
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    SOCKET_LISTENING: only local
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    AAAA_QUERY_ANALYSIS: Show AAAA queries
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    MAXDBDAYS: max age for stored queries is 365 days
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    RESOLVE_IPV6: Resolve IPv6 addresses
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    RESOLVE_IPV4: Resolve IPv4 addresses
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    DBINTERVAL: saving to DB file every minute
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    DBFILE: Using /etc/pihole/pihole-FTL.db
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    MAXLOGAGE: Importing up to 24.0 hours of log data
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    PRIVACYLEVEL: Set to 0
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    IGNORE_LOCALHOST: Show queries from localhost
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    BLOCKINGMODE: Null IPs for blocked domains
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    DBIMPORT: Importing history from database
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    PIDFILE: Using /run/pihole-FTL.pid
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    SOCKETFILE: Using /run/pihole/FTL.sock
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    MACVENDORDB: Using /etc/pihole/macvendor.db
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    GRAVITYDB: Using /etc/pihole/gravity.db
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    PARSE_ARP_CACHE: Active
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    CNAME_DEEP_INSPECT: Active
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    DELAY_STARTUP: No delay requested.
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    NICE: Set process niceness to -10 (default)
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    MAXNETAGE: Removing IP addresses and host names from network table after 365 days
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    NAMES_FROM_NETDB: Enabled, trying to get names from network database
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    EDNS0_ECS: Overwrite client from ECS information
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    REFRESH_HOSTNAMES: Periodically refreshing IPv4 names
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.711 1294888M]    RATE_LIMIT: Rate-limiting client making more than 5000 queries in 60 seconds
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    LOCAL_IPV4: Automatic interface-dependent detection of address
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    LOCAL_IPV6: Automatic interface-dependent detection of address
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    BLOCK_IPV4: Automatic interface-dependent detection of address
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    BLOCK_IPV6: Automatic interface-dependent detection of address
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    SHOW_DNSSEC: Enabled, showing automatically generated DNSSEC queries
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    MOZILLA_CANARY: Enabled
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    PIHOLE_PTR: internal PTR generation enabled (pi.hole)
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    ADDR2LINE: Enabled
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    REPLY_WHEN_BUSY: Drop queries when the database is busy
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    BLOCK_TTL: 2 seconds
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    BLOCK_ICLOUD_PR: Enabled
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    CHECK_LOAD: Enabled
Mar 25 07:49:54 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    CHECK_SHMEM: Warning if shared-memory usage exceeds 90%
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M]    CHECK_DISK: Warning if certain disk usage exceeds 90%
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M] Finished config file parsing
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M] Creating mutex
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.712 1294888M] Creating mutex
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.713 1294888M] PID of FTL process: 1294888
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.714 1294888M] Database version is 12
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.714 1294888M] Resizing "FTL-strings" from 40960 to (81920 * 1) == 81920 (/dev/shm: 712.7KB used, 2.0GB total, FTL uses 700.8KB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.714 1294888M] Imported 0 alias-clients
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.715 1294888M] Database successfully initialized
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.770 1294888M] New upstream server: 1.0.0.1:53 (0/512)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.838 1294888M] New upstream server: 9.9.9.9:53 (1/512)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.911 1294888M] Resizing "FTL-queries" from 229376 to (8192 * 56) == 458752 (/dev/shm: 753.7KB used, 2.0GB total, FTL uses 741.7KB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.917 1294888M] New upstream server: 149.112.112.112:53 (2/512)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:54.921 1294888M] New upstream server: 1.1.1.1:53 (3/512)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.036 1294888M] Resizing "FTL-queries" from 458752 to (12288 * 56) == 688128 (/dev/shm: 983.0KB used, 2.0GB total, FTL uses 971.1KB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.154 1294888M] Resizing "FTL-queries" from 688128 to (16384 * 56) == 917504 (/dev/shm: 1.2MB used, 2.0GB total, FTL uses 1.2MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.225 1294888M] Resizing "FTL-domains" from 12288 to (1024 * 24) == 24576 (/dev/shm: 1.4MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.230 1294888M] Resizing "FTL-queries" from 917504 to (20480 * 56) == 1146880 (/dev/shm: 1.5MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.316 1294888M] Resizing "FTL-queries" from 1146880 to (24576 * 56) == 1376256 (/dev/shm: 1.7MB used, 2.0GB total, FTL uses 1.7MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.380 1294888M] Resizing "FTL-queries" from 1376256 to (28672 * 56) == 1605632 (/dev/shm: 1.9MB used, 2.0GB total, FTL uses 1.9MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.434 1294888M] Resizing "FTL-queries" from 1605632 to (32768 * 56) == 1835008 (/dev/shm: 2.1MB used, 2.0GB total, FTL uses 2.1MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.513 1294888M] Resizing "FTL-queries" from 1835008 to (36864 * 56) == 2064384 (/dev/shm: 2.4MB used, 2.0GB total, FTL uses 2.4MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.590 1294888M] Resizing "FTL-queries" from 2064384 to (40960 * 56) == 2293760 (/dev/shm: 2.6MB used, 2.0GB total, FTL uses 2.6MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.655 1294888M] Resizing "FTL-queries" from 2293760 to (45056 * 56) == 2523136 (/dev/shm: 2.8MB used, 2.0GB total, FTL uses 2.8MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.739 1294888M] Resizing "FTL-domains" from 24576 to (1536 * 24) == 36864 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.0MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.778 1294888M] Resizing "FTL-queries" from 2523136 to (49152 * 56) == 2752512 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.1MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.871 1294888M] Resizing "FTL-queries" from 2752512 to (53248 * 56) == 2981888 (/dev/shm: 3.3MB used, 2.0GB total, FTL uses 3.3MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:55.942 1294888M] Resizing "FTL-queries" from 2981888 to (57344 * 56) == 3211264 (/dev/shm: 3.5MB used, 2.0GB total, FTL uses 3.5MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.042 1294888M] Resizing "FTL-queries" from 3211264 to (61440 * 56) == 3440640 (/dev/shm: 3.8MB used, 2.0GB total, FTL uses 3.7MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.112 1294888M] Resizing "FTL-queries" from 3440640 to (65536 * 56) == 3670016 (/dev/shm: 4.0MB used, 2.0GB total, FTL uses 4.0MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.210 1294888M] Resizing "FTL-queries" from 3670016 to (69632 * 56) == 3899392 (/dev/shm: 4.2MB used, 2.0GB total, FTL uses 4.2MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.289 1294888M] Resizing "FTL-queries" from 3899392 to (73728 * 56) == 4128768 (/dev/shm: 4.4MB used, 2.0GB total, FTL uses 4.4MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.360 1294888M] Resizing "FTL-queries" from 4128768 to (77824 * 56) == 4358144 (/dev/shm: 4.7MB used, 2.0GB total, FTL uses 4.7MB)
Mar 25 07:49:56 llserver pihole-FTL[1294888]: [2024-03-25 07:49:56.415 1294888M] Resizing "FTL-queries" from 4358144 to (81920 * 56) == 4587520 (/dev/shm: 4.9MB used, 2.0GB total, FTL uses 4.9MB)
Mar 25 07:49:57 llserver pihole-FTL[1294888]: [2024
Mar 25 07:55:55 llserver systemd[1]: pihole-FTL.service: Succeeded.
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] Using log file /var/log/pihole/FTL.log
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] ########## FTL started on llserver.lionslair.net.au! ##########
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] FTL branch: fix/ede_neterr
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] FTL version: vDev-d0f1682
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] FTL commit: d0f16824
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] FTL date: 2024-03-24 12:42:49 +0100
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] FTL user: pihole
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] Compiled for x86_64 (compiled on CI) using gcc (Debian 8.3.0-6) 8.3.0
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    SOCKET_LISTENING: only local
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    AAAA_QUERY_ANALYSIS: Show AAAA queries
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    MAXDBDAYS: max age for stored queries is 365 days
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    RESOLVE_IPV6: Resolve IPv6 addresses
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    RESOLVE_IPV4: Resolve IPv4 addresses
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    DBINTERVAL: saving to DB file every minute
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    DBFILE: Using /etc/pihole/pihole-FTL.db
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    MAXLOGAGE: Importing up to 24.0 hours of log data
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    PRIVACYLEVEL: Set to 0
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    IGNORE_LOCALHOST: Show queries from localhost
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    BLOCKINGMODE: Null IPs for blocked domains
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    DBIMPORT: Importing history from database
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    PIDFILE: Using /run/pihole-FTL.pid
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    SOCKETFILE: Using /run/pihole/FTL.sock
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    MACVENDORDB: Using /etc/pihole/macvendor.db
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    GRAVITYDB: Using /etc/pihole/gravity.db
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    PARSE_ARP_CACHE: Active
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    CNAME_DEEP_INSPECT: Active
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    DELAY_STARTUP: No delay requested.
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.537 1299648M]    BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    NICE: Set process niceness to -10 (default)
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    MAXNETAGE: Removing IP addresses and host names from network table after 365 days
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    NAMES_FROM_NETDB: Enabled, trying to get names from network database
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    EDNS0_ECS: Overwrite client from ECS information
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    REFRESH_HOSTNAMES: Periodically refreshing IPv4 names
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    RATE_LIMIT: Rate-limiting client making more than 5000 queries in 60 seconds
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    LOCAL_IPV4: Automatic interface-dependent detection of address
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    LOCAL_IPV6: Automatic interface-dependent detection of address
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    BLOCK_IPV4: Automatic interface-dependent detection of address
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    BLOCK_IPV6: Automatic interface-dependent detection of address
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    SHOW_DNSSEC: Enabled, showing automatically generated DNSSEC queries
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    MOZILLA_CANARY: Enabled
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    PIHOLE_PTR: internal PTR generation enabled (pi.hole)
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    ADDR2LINE: Enabled
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    REPLY_WHEN_BUSY: Drop queries when the database is busy
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    BLOCK_TTL: 2 seconds
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    BLOCK_ICLOUD_PR: Enabled
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    CHECK_LOAD: Enabled
Mar 25 07:55:55 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    CHECK_SHMEM: Warning if shared-memory usage exceeds 90%
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M]    CHECK_DISK: Warning if certain disk usage exceeds 90%
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M] Finished config file parsing
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M] Creating mutex
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.538 1299648M] Creating mutex
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.549 1299648M] PID of FTL process: 1299648
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.549 1299648M] Database version is 12
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.549 1299648M] Resizing "FTL-strings" from 40960 to (81920 * 1) == 81920 (/dev/shm: 712.7KB used, 2.0GB total, FTL uses 700.8KB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.550 1299648M] Imported 0 alias-clients
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.550 1299648M] Database successfully initialized
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.617 1299648M] New upstream server: 1.0.0.1:53 (0/512)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.674 1299648M] New upstream server: 9.9.9.9:53 (1/512)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.739 1299648M] New upstream server: 149.112.112.112:53 (2/512)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.741 1299648M] New upstream server: 1.1.1.1:53 (3/512)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.745 1299648M] Resizing "FTL-queries" from 229376 to (8192 * 56) == 458752 (/dev/shm: 753.7KB used, 2.0GB total, FTL uses 741.7KB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.776 1299648M] Resizing "FTL-queries" from 458752 to (12288 * 56) == 688128 (/dev/shm: 983.0KB used, 2.0GB total, FTL uses 971.1KB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.800 1299648M] Resizing "FTL-queries" from 688128 to (16384 * 56) == 917504 (/dev/shm: 1.2MB used, 2.0GB total, FTL uses 1.2MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.821 1299648M] Resizing "FTL-domains" from 12288 to (1024 * 24) == 24576 (/dev/shm: 1.4MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.824 1299648M] Resizing "FTL-queries" from 917504 to (20480 * 56) == 1146880 (/dev/shm: 1.5MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.846 1299648M] Resizing "FTL-queries" from 1146880 to (24576 * 56) == 1376256 (/dev/shm: 1.7MB used, 2.0GB total, FTL uses 1.7MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.868 1299648M] Resizing "FTL-queries" from 1376256 to (28672 * 56) == 1605632 (/dev/shm: 1.9MB used, 2.0GB total, FTL uses 1.9MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.890 1299648M] Resizing "FTL-queries" from 1605632 to (32768 * 56) == 1835008 (/dev/shm: 2.1MB used, 2.0GB total, FTL uses 2.1MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.916 1299648M] Resizing "FTL-queries" from 1835008 to (36864 * 56) == 2064384 (/dev/shm: 2.4MB used, 2.0GB total, FTL uses 2.4MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.950 1299648M] Resizing "FTL-queries" from 2064384 to (40960 * 56) == 2293760 (/dev/shm: 2.6MB used, 2.0GB total, FTL uses 2.6MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:55.984 1299648M] Resizing "FTL-queries" from 2293760 to (45056 * 56) == 2523136 (/dev/shm: 2.8MB used, 2.0GB total, FTL uses 2.8MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.004 1299648M] Resizing "FTL-domains" from 24576 to (1536 * 24) == 36864 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.0MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.019 1299648M] Resizing "FTL-queries" from 2523136 to (49152 * 56) == 2752512 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.1MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.049 1299648M] Resizing "FTL-queries" from 2752512 to (53248 * 56) == 2981888 (/dev/shm: 3.3MB used, 2.0GB total, FTL uses 3.3MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.090 1299648M] Resizing "FTL-queries" from 2981888 to (57344 * 56) == 3211264 (/dev/shm: 3.5MB used, 2.0GB total, FTL uses 3.5MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.133 1299648M] Resizing "FTL-queries" from 3211264 to (61440 * 56) == 3440640 (/dev/shm: 3.8MB used, 2.0GB total, FTL uses 3.7MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.163 1299648M] Resizing "FTL-queries" from 3440640 to (65536 * 56) == 3670016 (/dev/shm: 4.0MB used, 2.0GB total, FTL uses 4.0MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.208 1299648M] Resizing "FTL-queries" from 3670016 to (69632 * 56) == 3899392 (/dev/shm: 4.2MB used, 2.0GB total, FTL uses 4.2MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.254 1299648M] Resizing "FTL-queries" from 3899392 to (73728 * 56) == 4128768 (/dev/shm: 4.4MB used, 2.0GB total, FTL uses 4.4MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.299 1299648M] Resizing "FTL-queries" from 4128768 to (77824 * 56) == 4358144 (/dev/shm: 4.7MB used, 2.0GB total, FTL uses 4.7MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024-03-25 07:55:56.332 1299648M] Resizing "FTL-queries" from 4358144 to (81920 * 56) == 4587520 (/dev/shm: 4.9MB used, 2.0GB total, FTL uses 4.9MB)
Mar 25 07:55:56 llserver pihole-FTL[1299648]: [2024
Mar 25 07:56:41 llserver systemd[1]: pihole-FTL.service: Succeeded.
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] Using log file /var/log/pihole/FTL.log
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] ########## FTL started on llserver.lionslair.net.au! ##########
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] FTL branch: fix/ede_neterr
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] FTL version: vDev-d0f1682
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] FTL commit: d0f16824
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] FTL date: 2024-03-24 12:42:49 +0100
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] FTL user: pihole
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] Compiled for x86_64 (compiled on CI) using gcc (Debian 8.3.0-6) 8.3.0
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    SOCKET_LISTENING: only local
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    AAAA_QUERY_ANALYSIS: Show AAAA queries
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    MAXDBDAYS: max age for stored queries is 365 days
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    RESOLVE_IPV6: Resolve IPv6 addresses
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    RESOLVE_IPV4: Resolve IPv4 addresses
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    DBINTERVAL: saving to DB file every minute
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    DBFILE: Using /etc/pihole/pihole-FTL.db
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    MAXLOGAGE: Importing up to 24.0 hours of log data
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    PRIVACYLEVEL: Set to 0
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    IGNORE_LOCALHOST: Show queries from localhost
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.485 1300005M]    BLOCKINGMODE: Null IPs for blocked domains
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    DBIMPORT: Importing history from database
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    PIDFILE: Using /run/pihole-FTL.pid
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    SOCKETFILE: Using /run/pihole/FTL.sock
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    MACVENDORDB: Using /etc/pihole/macvendor.db
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    GRAVITYDB: Using /etc/pihole/gravity.db
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    PARSE_ARP_CACHE: Active
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    CNAME_DEEP_INSPECT: Active
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    DELAY_STARTUP: No delay requested.
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    NICE: Set process niceness to -10 (default)
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    MAXNETAGE: Removing IP addresses and host names from network table after 365 days
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    NAMES_FROM_NETDB: Enabled, trying to get names from network database
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    EDNS0_ECS: Overwrite client from ECS information
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    REFRESH_HOSTNAMES: Periodically refreshing IPv4 names
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    RATE_LIMIT: Rate-limiting client making more than 5000 queries in 60 seconds
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    LOCAL_IPV4: Automatic interface-dependent detection of address
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    LOCAL_IPV6: Automatic interface-dependent detection of address
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    BLOCK_IPV4: Automatic interface-dependent detection of address
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    BLOCK_IPV6: Automatic interface-dependent detection of address
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    SHOW_DNSSEC: Enabled, showing automatically generated DNSSEC queries
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    MOZILLA_CANARY: Enabled
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    PIHOLE_PTR: internal PTR generation enabled (pi.hole)
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    ADDR2LINE: Enabled
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    REPLY_WHEN_BUSY: Drop queries when the database is busy
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    BLOCK_TTL: 2 seconds
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    BLOCK_ICLOUD_PR: Enabled
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    CHECK_LOAD: Enabled
Mar 25 07:56:41 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    CHECK_SHMEM: Warning if shared-memory usage exceeds 90%
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M]    CHECK_DISK: Warning if certain disk usage exceeds 90%
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M] Finished config file parsing
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M] Creating mutex
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.486 1300005M] Creating mutex
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.489 1300005M] PID of FTL process: 1300005
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.491 1300005M] Database version is 12
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.492 1300005M] Resizing "FTL-strings" from 40960 to (81920 * 1) == 81920 (/dev/shm: 712.7KB used, 2.0GB total, FTL uses 700.8KB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.492 1300005M] Imported 0 alias-clients
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.492 1300005M] Database successfully initialized
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.565 1300005M] New upstream server: 1.0.0.1:53 (0/512)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.581 1300005M] New upstream server: 9.9.9.9:53 (1/512)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.618 1300005M] New upstream server: 149.112.112.112:53 (2/512)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.619 1300005M] New upstream server: 1.1.1.1:53 (3/512)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.630 1300005M] Resizing "FTL-queries" from 229376 to (8192 * 56) == 458752 (/dev/shm: 753.7KB used, 2.0GB total, FTL uses 741.7KB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.675 1300005M] Resizing "FTL-queries" from 458752 to (12288 * 56) == 688128 (/dev/shm: 983.0KB used, 2.0GB total, FTL uses 971.1KB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.704 1300005M] Resizing "FTL-queries" from 688128 to (16384 * 56) == 917504 (/dev/shm: 1.2MB used, 2.0GB total, FTL uses 1.2MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.722 1300005M] Resizing "FTL-domains" from 12288 to (1024 * 24) == 24576 (/dev/shm: 1.4MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.726 1300005M] Resizing "FTL-queries" from 917504 to (20480 * 56) == 1146880 (/dev/shm: 1.5MB used, 2.0GB total, FTL uses 1.4MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.747 1300005M] Resizing "FTL-queries" from 1146880 to (24576 * 56) == 1376256 (/dev/shm: 1.7MB used, 2.0GB total, FTL uses 1.7MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.768 1300005M] Resizing "FTL-queries" from 1376256 to (28672 * 56) == 1605632 (/dev/shm: 1.9MB used, 2.0GB total, FTL uses 1.9MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.788 1300005M] Resizing "FTL-queries" from 1605632 to (32768 * 56) == 1835008 (/dev/shm: 2.1MB used, 2.0GB total, FTL uses 2.1MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.813 1300005M] Resizing "FTL-queries" from 1835008 to (36864 * 56) == 2064384 (/dev/shm: 2.4MB used, 2.0GB total, FTL uses 2.4MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.843 1300005M] Resizing "FTL-queries" from 2064384 to (40960 * 56) == 2293760 (/dev/shm: 2.6MB used, 2.0GB total, FTL uses 2.6MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.877 1300005M] Resizing "FTL-queries" from 2293760 to (45056 * 56) == 2523136 (/dev/shm: 2.8MB used, 2.0GB total, FTL uses 2.8MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.892 1300005M] Resizing "FTL-domains" from 24576 to (1536 * 24) == 36864 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.0MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.908 1300005M] Resizing "FTL-queries" from 2523136 to (49152 * 56) == 2752512 (/dev/shm: 3.1MB used, 2.0GB total, FTL uses 3.1MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.936 1300005M] Resizing "FTL-queries" from 2752512 to (53248 * 56) == 2981888 (/dev/shm: 3.3MB used, 2.0GB total, FTL uses 3.3MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.966 1300005M] Resizing "FTL-queries" from 2981888 to (57344 * 56) == 3211264 (/dev/shm: 3.5MB used, 2.0GB total, FTL uses 3.5MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:41.995 1300005M] Resizing "FTL-queries" from 3211264 to (61440 * 56) == 3440640 (/dev/shm: 3.8MB used, 2.0GB total, FTL uses 3.7MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:42.024 1300005M] Resizing "FTL-queries" from 3440640 to (65536 * 56) == 3670016 (/dev/shm: 4.0MB used, 2.0GB total, FTL uses 4.0MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:42.065 1300005M] Resizing "FTL-queries" from 3670016 to (69632 * 56) == 3899392 (/dev/shm: 4.2MB used, 2.0GB total, FTL uses 4.2MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:42.108 1300005M] Resizing "FTL-queries" from 3899392 to (73728 * 56) == 4128768 (/dev/shm: 4.4MB used, 2.0GB total, FTL uses 4.4MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:42.160 1300005M] Resizing "FTL-queries" from 4128768 to (77824 * 56) == 4358144 (/dev/shm: 4.7MB used, 2.0GB total, FTL uses 4.7MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024-03-25 07:56:42.203 1300005M] Resizing "FTL-queries" from 4358144 to (81920 * 56) == 4587520 (/dev/shm: 4.9MB used, 2.0GB total, FTL uses 4.9MB)
Mar 25 07:56:42 llserver pihole-FTL[1300005]: [2024

@lionslair
Copy link

got same output with tailscale not running. I can access github

 Please note that changing branches severely alters your Pi-hole subsystems
  Features that work on the master branch, may not on a development branch
  This feature is NOT supported unless a Pi-hole developer explicitly asks!
  Have you read and understood this? [y/N] y

  [✓] Branch fix/ede_neterr exists
  [i] Switching to branch: "fix/ede_neterr" from "fix/ede_neterr"
  [✓] Downloading and Installing FTL
  [✓] Restarting pihole-FTL service...
  [✓] Enabling pihole-FTL service to start on reboot...
fatal: unable to access 'https://github.com/pi-hole/pi-hole/': Could not resolve host: github.com
fatal: unable to access 'https://github.com/pi-hole/web/': Could not resolve host: github.com
fatal: unable to access 'https://github.com/pi-hole/FTL/': Could not resolve host: github.com

@DL6ER
Copy link
Member

DL6ER commented Mar 25, 2024

Maybe it is a concurrency issue when FTL is still restarting and taking a bit longer than it normally would (or you have configured a startup delay). In any case, as long as the checkout has worked (pihole-FTL -b reporting fix/ede_neterr or pihole -v reporting the same branch), everything is prepared and we can sit down and wait for the next incident to happen.

You may want to try configuring a different nameserver than 127.0.0.1 at /etc/resolv.conf, this has been the new default for quite some time in Pi-hole.

@lionslair
Copy link

Maybe it is a concurrency issue when FTL is still restarting and taking a bit longer than it normally would (or you have configured a startup delay). In any case, as long as the checkout has worked (pihole-FTL -b reporting fix/ede_neterr or pihole -v reporting the same branch), everything is prepared and we can sit down and wait for the next incident to happen.

You may want to try configuring a different nameserver than 127.0.0.1 at /etc/resolv.conf, this has been the new default for quite some time in Pi-hole.

╰─$ pihole -v  
  Pi-hole version is v5.17.3 (Latest: v5.17.3)
  web version is v5.21 (Latest: v5.21)
  FTL version is fix/ede_neterr vDev-d0f1682 (Latest: v5.25.1)

Have updated the names servers to match the two dns server like the pi has

nameserver 192.168.1.103
nameserver 192.168.1.104

@lionslair
Copy link

lionslair commented Mar 30, 2024

Ok I am getting it again right now.

Sample of some output for different domains.

Mar 31 06:56:59 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#59582 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#48835 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#48835 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/A at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#37674 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#37674 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#41889 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#41889 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/A at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#59707 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#59707 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#40432 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#40432 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#59601 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#59601 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/A at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#43361 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#43361 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/A at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#44747 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#44747 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#59356 (incoming-telemetry.thunderbird.net): query (cache) 'incoming-telemetry.thunderbird.net/A/IN' denied
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#59356 (incoming-telemetry.thunderbird.net): query failed (REFUSED) for incoming-telemetry.thunderbird.net/IN/A at query.c:5560
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#55507 (incoming-telemetry.thunderbird.net): query (cache) 'incoming-telemetry.thunderbird.net/AAAA/IN' denied
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#55507 (incoming-telemetry.thunderbird.net): query failed (REFUSED) for incoming-telemetry.thunderbird.net/IN/AAAA at query.c:5560
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6a80428c0 100.64.0.5#43890 (incoming-telemetry.thunderbird.net): query (cache) 'incoming-telemetry.thunderbird.net/A/IN' denied
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6a80428c0 100.64.0.5#43890 (incoming-telemetry.thunderbird.net): query failed (REFUSED) for incoming-telemetry.thunderbird.net/IN/A at query.c:5560
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#41132 (incoming-telemetry.thunderbird.net): query (cache) 'incoming-telemetry.thunderbird.net/AAAA/IN' denied
Mar 31 06:57:07 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#41132 (incoming-telemetry.thunderbird.net): query failed (REFUSED) for incoming-telemetry.thunderbird.net/IN/AAAA at query.c:5560
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#33691 (livewire.laravel.com): query (cache) 'livewire.laravel.com/A/IN' denied
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#33691 (livewire.laravel.com): query failed (REFUSED) for livewire.laravel.com/IN/A at query.c:5560
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6b05dda00 100.64.0.5#38580 (livewire.laravel.com): query (cache) 'livewire.laravel.com/A/IN' denied
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6b05dda00 100.64.0.5#38580 (livewire.laravel.com): query failed (REFUSED) for livewire.laravel.com/IN/A at query.c:5560
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#52375 (livewire.laravel.com): query (cache) 'livewire.laravel.com/A/IN' denied
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6a804dcf0 100.64.0.5#52375 (livewire.laravel.com): query failed (REFUSED) for livewire.laravel.com/IN/A at query.c:5560
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6b05dda00 100.64.0.5#58357 (livewire.laravel.com): query (cache) 'livewire.laravel.com/A/IN' denied
Mar 31 07:04:59 llserver named[2795963]: client @0x7fa6b05dda00 100.64.0.5#58357 (livewire.laravel.com): query failed (REFUSED) for livewire.laravel.com/IN/A at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#48405 (images.unsplash.com): query (cache) 'images.unsplash.com/AAAA/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b0679bd0 100.64.0.5#48405 (images.unsplash.com): query failed (REFUSED) for images.unsplash.com/IN/AAAA at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#57470 (support.mozilla.org): query (cache) 'support.mozilla.org/AAAA/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#57470 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/AAAA at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#52239 (support.mozilla.org): query (cache) 'support.mozilla.org/A/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#52239 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/A at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#48673 (support.mozilla.org): query (cache) 'support.mozilla.org/AAAA/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#48673 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/AAAA at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#37712 (support.mozilla.org): query (cache) 'support.mozilla.org/AAAA/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#37712 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/AAAA at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#41512 (support.mozilla.org): query (cache) 'support.mozilla.org/A/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#41512 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/A at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#40954 (support.mozilla.org): query (cache) 'support.mozilla.org/A/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#40954 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/A at query.c:5560
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#52006 (support.mozilla.org): query (cache) 'support.mozilla.org/AAAA/IN' denied
Mar 31 07:05:00 llserver named[2795963]: client @0x7fa6b09978a0 100.64.0.5#52006 (support.mozilla.org): query failed (REFUSED) for support.mozilla.org/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a8059560 100.64.0.5#39804 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#57914 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#57914 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#54659 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#54659 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#37225 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#37225 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#39365 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#39365 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#42305 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#42305 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#48214 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#48214 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#38320 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#38320 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#33840 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#33840 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#38156 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#38156 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#46204 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b085b7b0 100.64.0.5#46204 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#57899 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#57899 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#55234 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#55234 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a8059560 100.64.0.5#37118 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6a8059560 100.64.0.5#37118 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#46495 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/A/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#46495 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/A at query.c:5560
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#55622 (www.wanneroocentral.com.au): query (cache) 'www.wanneroocentral.com.au/AAAA/IN' denied
Mar 31 07:06:53 llserver named[2795963]: client @0x7fa6b0857810 100.64.0.5#55622 (www.wanneroocentral.com.au): query failed (REFUSED) for www.wanneroocentral.com.au/IN/AAAA at query.c:5560

All seems directly related to IPV6. I have copy of the logs before reboot. anything specific you want to see. Funny not every domain is blocked there is stuff getting through. However a lot are blocked.

Again after reboot all is back to normal. Those blocked domains are working

@lionslair
Copy link

lionslair commented Mar 30, 2024

hmm looking through the logs earlier in syslog. It seems bind is being started just after midnight. That is where the named errors start.

root@llserver:/var/log# grc cat syslog.1 | grep named
Mar 30 06:23:35 llserver tailscaled[3303866]: netcheck: netcheck.runProbe: named node "999" has no address
Mar 30 06:23:35 llserver tailscaled[3303866]: message repeated 2 times: [ netcheck: netcheck.runProbe: named node "999" has no address]
Mar 30 20:05:46 llserver tailscaled[3303866]: netcheck: netcheck.runProbe: named node "999" has no address
Mar 30 20:05:46 llserver tailscaled[3303866]: message repeated 2 times: [ netcheck: netcheck.runProbe: named node "999" has no address]
Mar 31 00:00:03 llserver named[2795963]: starting BIND 9.16.48-Ubuntu (Extended Support Version) <id:0dab57e>
Mar 31 00:00:03 llserver named[2795963]: running on Linux x86_64 5.4.0-174-generic #193-Ubuntu SMP Thu Mar 7 14:29:28 UTC 2024
Mar 31 00:00:03 llserver named[2795963]: built with '--build=x86_64-linux-gnu' '--prefix=/usr' '--includedir=/usr/include' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--sysconfdir=/etc' '--localstatedir=/var' '--disable-silent-rules' '--libdir=/usr/lib/x86_64-linux-gnu' '--runstatedir=/run' '--disable-maintainer-mode' '--disable-dependency-tracking' '--libdir=/usr/lib/x86_64-linux-gnu' '--sysconfdir=/etc/bind' '--with-python=python3' '--localstatedir=/' '--enable-threads' '--enable-largefile' '--with-libtool' '--enable-shared' '--enable-static' '--with-gost=no' '--with-openssl=/usr' '--with-gssapi=/usr' '--with-libidn2' '--with-json-c' '--with-lmdb=/usr' '--with-gnu-ld' '--with-maxminddb' '--with-atf=no' '--enable-ipv6' '--enable-rrl' '--enable-filter-aaaa' '--disable-native-pkcs11' '--disable-isc-spnego' 'build_alias=x86_64-linux-gnu' 'CFLAGS=-g -O2 -fdebug-prefix-map=/build/bind9-jSiMEl/bind9-9.16.48=. -fstack-protector-strong -Wformat -Werror=format-security -fno-strict-aliasing -fno-delete-null-pointer-checks -DNO_VERSION_DATE -DDIG_SIGCHASE' 'LDFLAGS=-Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now' 'CPPFLAGS=-Wdate-time -D_FORTIFY_SOURCE=2'
Mar 31 00:00:03 llserver named[2795963]: running as: named -f -u bind
Mar 31 00:00:03 llserver named[2795963]: compiled by GCC 9.4.0
Mar 31 00:00:03 llserver named[2795963]: compiled with OpenSSL version: OpenSSL 1.1.1f  31 Mar 2020
Mar 31 00:00:03 llserver named[2795963]: linked to OpenSSL version: OpenSSL 1.1.1f  31 Mar 2020
Mar 31 00:00:03 llserver named[2795963]: compiled with libuv version: 1.34.2
Mar 31 00:00:03 llserver named[2795963]: linked to libuv version: 1.34.2
Mar 31 00:00:03 llserver named[2795963]: compiled with libxml2 version: 2.9.10
Mar 31 00:00:03 llserver named[2795963]: linked to libxml2 version: 20914
Mar 31 00:00:03 llserver named[2795963]: compiled with json-c version: 0.13.1
Mar 31 00:00:03 llserver named[2795963]: linked to json-c version: 0.13.1
Mar 31 00:00:03 llserver named[2795963]: compiled with zlib version: 1.2.11
Mar 31 00:00:03 llserver named[2795963]: linked to zlib version: 1.2.11
Mar 31 00:00:03 llserver named[2795963]: ----------------------------------------------------
Mar 31 00:00:03 llserver named[2795963]: BIND 9 is maintained by Internet Systems Consortium,
Mar 31 00:00:03 llserver named[2795963]: Inc. (ISC), a non-profit 501(c)(3) public-benefit 
Mar 31 00:00:03 llserver named[2795963]: corporation.  Support and training for BIND 9 are 
Mar 31 00:00:03 llserver named[2795963]: available at https://www.isc.org/support
Mar 31 00:00:03 llserver named[2795963]: ----------------------------------------------------
Mar 31 00:00:03 llserver named[2795963]: adjusted limit on open files from 524288 to 1048576
Mar 31 00:00:03 llserver named[2795963]: found 2 CPUs, using 2 worker threads
Mar 31 00:00:03 llserver named[2795963]: using 2 UDP listeners per interface
Mar 31 00:00:03 llserver named[2795963]: using up to 21000 sockets
Mar 31 00:00:03 llserver named[2795963]: DNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
Mar 31 00:00:03 llserver named[2795963]: DS algorithms: SHA-1 SHA-256 SHA-384
Mar 31 00:00:03 llserver named[2795963]: HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
Mar 31 00:00:03 llserver named[2795963]: TKEY mode 2 support (Diffie-Hellman): yes
Mar 31 00:00:03 llserver named[2795963]: TKEY mode 3 support (GSS-API): yes
Mar 31 00:00:03 llserver named[2795963]: loading configuration from '/etc/bind/named.conf'
Mar 31 00:00:04 llserver named[2795963]: reading built-in trust anchors from file '/etc/bind/bind.keys'
Mar 31 00:00:04 llserver named[2795963]: looking for GeoIP2 databases in '/usr/share/GeoIP'
Mar 31 00:00:04 llserver named[2795963]: using default UDP/IPv4 port range: [32768, 60999]
Mar 31 00:00:04 llserver named[2795963]: using default UDP/IPv6 port range: [32768, 60999]
Mar 31 00:00:04 llserver named[2795963]: listening on IPv4 interface lo, 127.0.0.1#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv4 interface enp2s0, 192.168.1.103#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv4 interface docker0, 172.17.0.1#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv4 interface tailscale0, 100.64.0.1#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: IPv6 socket API is incomplete; explicitly binding to each IPv6 address separately
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface lo, ::1#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface enp2s0, fe80::2a92:4aff:fe30:5bcc%2#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface docker0, fe80::42:8fff:fe34:a9ba%4#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth2878e33, fe80::147c:8cff:fe1a:b252%8#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth14b6175, fe80::2ca3:ffff:fef3:feea%12#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth812b78e, fe80::80dd:c4ff:fee2:1099%14#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth43f634f, fe80::501a:95ff:fe29:7bb9%16#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth8874e6c, fe80::c49e:b4ff:fee0:d880%18#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface veth03438e0, fe80::f458:e8ff:fe3c:a860%50#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface vethcb81b91, fe80::fcb1:1dff:fe5e:8819%52#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface tailscale0, fd7a:115c:a1e0::1#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: listening on IPv6 interface tailscale0, fe80::3a3:549d:3413:d230%53#53
Mar 31 00:00:04 llserver named[2795963]: creating TCP socket: address in use
Mar 31 00:00:04 llserver named[2795963]: generating session key for dynamic DNS
Mar 31 00:00:04 llserver named[2795963]: sizing zone task pool based on 6 zones
Mar 31 00:00:04 llserver named[2795963]: none:90: 'max-cache-size 90%' - setting to 3414MB (out of 3793MB)
Mar 31 00:00:04 llserver named[2795963]: obtaining root key for view _default from '/etc/bind/bind.keys'
Mar 31 00:00:04 llserver named[2795963]: set up managed keys zone for view _default, file 'managed-keys.bind'
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 10.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 16.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 17.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 18.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 19.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 20.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 21.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 22.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 23.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 24.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 25.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 26.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 27.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 28.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 29.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 30.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 31.172.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 168.192.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 64.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 65.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 66.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 67.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 68.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 69.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 70.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 71.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 72.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 73.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 74.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 75.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 76.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 77.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 78.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 79.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 80.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 81.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 82.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 83.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 84.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 85.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 86.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 87.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 88.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 89.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 90.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 91.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 92.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 93.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 94.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 95.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 96.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 97.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 98.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 99.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 100.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 101.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 102.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 103.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 104.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 105.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 106.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 107.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 108.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 109.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 110.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 111.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 112.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 113.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 114.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 115.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 116.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 117.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 118.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 119.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 120.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 121.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 122.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 123.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 124.100.IN-ADDR.ARPA
Mar 31 00:00:04 llserver named[2795963]: automatic empty zone: 125.100.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 126.100.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 127.100.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 254.169.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 2.0.192.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 100.51.198.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 113.0.203.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 255.255.255.255.IN-ADDR.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: D.F.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 8.E.F.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 9.E.F.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: A.E.F.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: B.E.F.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: 8.B.D.0.1.0.0.2.IP6.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: EMPTY.AS112.ARPA
Mar 31 00:00:05 llserver named[2795963]: automatic empty zone: HOME.ARPA
Mar 31 00:00:05 llserver named[2795963]: configuring command channel from '/etc/bind/rndc.key'
Mar 31 00:00:05 llserver named[2795963]: command channel listening on 127.0.0.1#953
Mar 31 00:00:05 llserver named[2795963]: configuring command channel from '/etc/bind/rndc.key'
Mar 31 00:00:05 llserver named[2795963]: command channel listening on ::1#953
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#38203 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a80013a0 100.64.0.5#38203 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a8006c80 100.64.0.5#58051 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a8006c80 100.64.0.5#58051 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a800aef0 192.168.1.103#49296 (pihole.lionslair.net.au): query failed (zone not loaded) for pihole.lionslair.net.au/IN/A at query.c:5565
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#48873 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a800f350 100.64.0.5#48873 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a80135c0 100.64.0.5#55384 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a80135c0 100.64.0.5#55384 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#33248 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#33248 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a801baa0 100.64.0.5#39969 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6a801baa0 100.64.0.5#39969 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: managed-keys-zone: loaded serial 399
Mar 31 00:00:05 llserver named[2795963]: zone 0.in-addr.arpa/IN: loaded serial 1
Mar 31 00:00:05 llserver named[2795963]: zone 127.in-addr.arpa/IN: loaded serial 1
Mar 31 00:00:05 llserver named[2795963]: zone 255.in-addr.arpa/IN: loaded serial 1
Mar 31 00:00:05 llserver named[2795963]: /var/lib/bind/lionslair.net.au.hosts:15: ignoring out-of-zone data (22fac0cea965.lionslair.net.au.cname.bitly.com)
Mar 31 00:00:05 llserver named[2795963]: zone lionslair.net.au/IN: loaded serial 1617326505
Mar 31 00:00:05 llserver named[2795963]: zone localhost/IN: loaded serial 2
Mar 31 00:00:05 llserver named[2795963]: all zones loaded
Mar 31 00:00:05 llserver named[2795963]: running
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b120c990 100.64.0.5#37657 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b120c990 100.64.0.5#37657 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b120ef20 100.64.0.5#33545 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b120ef20 100.64.0.5#33545 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b1212730 100.64.0.5#43173 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/AAAA/IN' denied
Mar 31 00:00:05 llserver named[2795963]: client @0x7fa6b1212730 100.64.0.5#43173 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 00:00:05 llserver named[2795963]: managed-keys-zone: Key 20326 for zone . is now trusted (acceptance timer complete)
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6b1216150 100.64.0.5#46632 (edgeapi.slack.com): query (cache) 'edgeapi.slack.com/AAAA/IN' denied
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6b1216150 100.64.0.5#46632 (edgeapi.slack.com): query failed (REFUSED) for edgeapi.slack.com/IN/AAAA at query.c:5560
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#37779 (edgeapi.slack.com): query (cache) 'edgeapi.slack.com/A/IN' denied
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#37779 (edgeapi.slack.com): query failed (REFUSED) for edgeapi.slack.com/IN/A at query.c:5560
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#50575 (edgeapi.slack.com): query (cache) 'edgeapi.slack.com/A/IN' denied
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6a8017830 100.64.0.5#50575 (edgeapi.slack.com): query failed (REFUSED) for edgeapi.slack.com/IN/A at query.c:5560
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6b1216150 100.64.0.5#36552 (edgeapi.slack.com): query (cache) 'edgeapi.slack.com/AAAA/IN' denied
Mar 31 00:00:10 llserver named[2795963]: client @0x7fa6b1216150 100.64.0.5#36552 (edgeapi.slack.com): query failed (REFUSED) for edgeapi.slack.com/IN/AAAA at query.c:5560

@lionslair
Copy link

I used to run bind9 before pihole. Feel I could uninstall bind9 now but I am not sure what has caused it to now automatically start on sundays last few months.

@DL6ER
Copy link
Member

DL6ER commented Mar 31, 2024

Actually, I'd be more interested in the logs /var/og/pihole/pihole.log and FTL.log (in the same directory) around that time to hopefully see the cause of this. IIRC your bind is behind your Pi-hole, right? So when your Pi-hole causes the REFUSEs, it is expected that named doesn't get anything else.

@lionslair
Copy link

I've got them but need to jump on pc. Late here. Named is not usually running. It seems to now start at midnight on a Sunday. Could not find any reason why that is or what is starting it this morning. I've got the logs but was the syslog that lead me to when it started

@lionslair
Copy link

pihole-20240330-20240331.zip

pihole.log.1 is up to midnight on the 20240330
pihole.log is from midnight 20240331

sale with FTL.log and FTL.log.1 and added the other logs as reference. let me know if you want the full week.

@DL6ER
Copy link
Member

DL6ER commented Apr 1, 2024

When did it happen exactly? None of the logs you uploaded contains a single REFUSED query. They are also contiguous and do not show a gap at all:

  • pihole.log.1 from Mar 30 00:00:04 to Mar 31 00:00:09
  • pihole.log from Mar 31 00:00:10 to Mar 31 07:08:40

let me know if you want the full week.

We may need more, see above.

@DL6ER
Copy link
Member

DL6ER commented Apr 1, 2024

I looked again at your other logs from above, e.g.,

Mar 31 06:56:59 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#59582 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#48835 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied

We do not see these queries at all in your Pi-hole logs, the last query for us-west-1.wasabisys.com before that was at Mar 31 02:26:34 so hours before this log event - and it resolved just fine....

@lionslair
Copy link

I looked again at your other logs from above, e.g.,

Mar 31 06:56:59 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#59582 (us-west-1.wasabisys.com): query failed (REFUSED) for us-west-1.wasabisys.com/IN/AAAA at query.c:5560
Mar 31 06:57:01 llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#48835 (us-west-1.wasabisys.com): query (cache) 'us-west-1.wasabisys.com/A/IN' denied

We do not see these queries at all in your Pi-hole logs, the last query for us-west-1.wasabisys.com before that was at Mar 31 02:26:34 so hours before this log event - and it resolved just fine....

All of these lines

llserver named[2795963]: client @0x7fa6b02bd940 100.64.0.5#59582

Appeared in the syslog from named from just after midnight. which is why I posted that grepped snippet above.

Correct the pihole logs look fine. Not all but most requests are all coming from 127.0.0.1

I feel the issue is with named or bind9 starting at sunday at midnight again. It is not configured to start on boot so reboot kills it and things return to normal. I have no idea what has started triggering this but I will remove and purge the bind9 stuff and see if it occurs again this Sunday. My guess is this was unrelated to pihole but as I was only aware of pihole running not the pre-pihole setup was looking in the wrong place. On;y thing I haven't found is now pihole and named could possibly be sharing the same port. My guess is they are not.

@DL6ER
Copy link
Member

DL6ER commented Apr 2, 2024

sharing the same port

By default, no two sockets can be bound to the same combination of source address and source port. But things are a bit more complex. First, we should clarify that Pi-hole is not using SO_REUSEPORT. However, Pi-hole does indeed use SO_REUSEADDR which is where things get tricky and "port hijacking" might occur under certain circumstances. I don't know enough details concerning socket binding in named to assess if this may be the case. However, the mere observation that there are issues when the automatic (re)starting of named happens, seems to suggest there's a connection. The fact that a DNS resolver restarting "fixes" the situation might indicate that it is possible to "steal" the connection "back" through a resolver restart.
We could - in theory - automate this somehow, but it'd cause such situations to go unnoticed possibly causing more harm than anything else. It'd still be nice to see if the same REFUSED pops up again on the weekend as your log excerpts could allow us to craft specific warnings for the Pi-hole diagnosis system to make the user better aware of this situation.

Another possibility for such an issue could be, for instance, (as you don't know where/how named is started), that whatever starts named also configured some firewall rules which are causing issues here. But this is less likely because restarting the DNS resolver alone (without restating the entire server) is enough fix get things back to normal operation.

@crycode-de
Copy link

For me this issue seems to be related in some way to the log lines like

[2024-03-22 03:58:18.448 166M] WARNING in dnsmasq core: not giving name repeater1.home to the DHCP lease of fd00::3091:abff:fe19:6a00 because the name exists in /etc/pihole/custom.list with address fe80::3091:abff:fe19:6a00

which I had a lot for some devices.
I removed the local IPv6 entries which were noted in the log and now the FTL service is running fine since round about 9 days.

I'll keep watching it.

@lionslair
Copy link

sharing the same port

By default, no two sockets can be bound to the same combination of source address and source port. But things are a bit more complex. First, we should clarify that Pi-hole is not using SO_REUSEPORT. However, Pi-hole does indeed use SO_REUSEADDR which is where things get tricky and "port hijacking" might occur under certain circumstances. I don't know enough details concerning socket binding in named to assess if this may be the case. However, the mere observation that there are issues when the automatic (re)starting of named happens, seems to suggest there's a connection. The fact that a DNS resolver restarting "fixes" the situation might indicate that it is possible to "steal" the connection "back" through a resolver restart. We could - in theory - automate this somehow, but it'd cause such situations to go unnoticed possibly causing more harm than anything else. It'd still be nice to see if the same REFUSED pops up again on the weekend as your log excerpts could allow us to craft specific warnings for the Pi-hole diagnosis system to make the user better aware of this situation.

Another possibility for such an issue could be, for instance, (as you don't know where/how named is started), that whatever starts named also configured some firewall rules which are causing issues here. But this is less likely because restarting the DNS resolver alone (without restating the entire server) is enough fix get things back to normal operation.

You are right an I have said I believe this is a local issue not a pihole issue. I do understand what your saying and that is interesting. Because I had not realised NAMED/BIND was what was restarting until doing A RESTART OF THE SERVER I thought it was pihole. The two working together is very interesting. However I never did configure pihole when I set it up to pipe through bind9. I honestly count NOT find any use of bind in systemd or cron configs. I am sure there was something somewhere. Computers never just do what they feel like. I have uninstalled and purged the /etc/bind configs this morning. Will wait until this Sunday see if there is any more issues. I very strongly feel there won't be.

I do have another micro server I had at my parents configured with bind9/named. I could disable on that and install pihole but then no good way to test it as I don't want to break dns. Fully aware two services can not share a port so I know that seems silly.

From other devices they appear to have hit bind/named but from the server and the hosted docker containers they seems to use the pihole. Least that's how I think it looks like.

@lionslair
Copy link

No issues today. Nothing. All is working. So I feel the named / bond service that I discovered last week was my cause and issue.

Do I checkout back to the main branch than the special branch you made?

@DL6ER
Copy link
Member

DL6ER commented Apr 7, 2024

I'm glad we eventually solved your issue! The command you're looking for is

pihole checkout ftl master

@lionslair
Copy link

I'm glad we eventually solved your issue! The command you're looking for is

pihole checkout ftl master

Thank you for your help.

@DL6ER DL6ER closed this as completed Apr 7, 2024
@sts-ryan-holton
Copy link
Author

Has a fix been merged?

@DL6ER
Copy link
Member

DL6ER commented Apr 7, 2024

No, but I have seen no log lines from anyone besides @lionslair whose problem was solved. If you still experience this issue, you can surely reopen this ticket and we can go on if you have any of the log parts I've asked for further up here.

@bkodenkt
Copy link

bkodenkt commented Apr 9, 2024

For me, using the workaround described in #5608 (comment) did the trick to get a reliable, working system again. I eventually cleaned up the local DNS names i cluttered before, upgraded to the latest Pihole version, stopped using the workaround mentioned above and did not encounter the same problem again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants