On boot long FTL startup and web graphs blank until FTL restarted

[willis936]

Versions

• Pi-hole: v5.6
• AdminLTE: v5.8
• FTL: v5.11

Platform

• OS and version: Raspbian 10

• Platform: Raspberry Pi 4 Model B

Expected behavior

On boot FTL should start up within a minute and the web interface should show log graphs.

Actual behavior / bug

FTL takes a few minutes to start and afterwards the web interface does not populate the bar graphs until pihole restartdns is run. pihole repair does not fix the issue.

Steps to reproduce

Reboot. This is a build from about 18 months ago and it's had this behavior for most of its life. Maybe it has something to do with NTP taking some time to warm up and the default timestamp being too far in the past. With the use of unbound and unbound-resolvconf I think there may be a bootstrapping issue where the NTP time can't be pulled until the DNS resolver is working and the DNS resolver might not work if the system time isn't correct. There is also a local GPS/PPS module that chrony uses, but that might not be read in quickly enough.

Debug Token

• URL: https://tricorder.pi-hole.net/0Hfo58LO/

Screenshots

[willis936]

There is a GPS source feeding chrony that is kept hot and I have experimented with a service (https://selivan.github.io/2020/12/23/ntp-sync-time-before-starting-any-services.html) that attempts to force an NTP sync before other services, but the behavior is the same.

[jfb-pihole]

You have some oddities in your debug log.

First, the contents of your Pi-hole configuration file. Many of these lines should not be in this file - they are in file /etc/pihole/setupVars.conf.

-rw-rw-r-- 1 pihole root 415 Dec  7 02:29 /etc/pihole/pihole-FTL.conf
   PIHOLE_INTERFACE=eth0
   IPV4_ADDRESS=10.111.222.2/24
   IPV6_ADDRESS=fe80::5115:1395:1b5b:dcf5
   QUERY_LOGGING=false
   CACHE_SIZE=10000
   ADMIN_EMAIL=redacted
   WEBUIBOXEDLAYOUT=boxed
   WEBTHEME=default-darker
   BLOCKING_ENABLED=true
   DNSMASQ_LISTENING=single
   PIHOLE_DNS_1=127.0.0.1#5335
   PIHOLE_DNS_2=::1#5335
   DNS_FQDN_REQUIRED=false
   DNS_BOGUS_PRIV=false
   DNSSEC=true
   REV_SERVER=false
   AAAA_QUERY_ANALYSIS=yes
   PRIVACYLEVEL=0

Your query database is showing no traffic in the past 24 hours, which is inconsistent with your privacy and database settings.

   [2021-12-09 22:41:39.003 724M] Imported 0 queries from the long-term database
   [2021-12-09 22:41:39.004 724M]  -> Total DNS queries: 0
   [2021-12-09 22:41:39.004 724M]  -> Cached DNS queries: 0
   [2021-12-09 22:41:39.004 724M]  -> Forwarded DNS queries: 0
   [2021-12-09 22:41:39.004 724M]  -> Blocked DNS queries: 0
   [2021-12-09 22:41:39.004 724M]  -> Unknown DNS queries: 0
   [2021-12-09 22:41:39.004 724M]  -> Unique domains: 0
   [2021-12-09 22:41:39.004 724M]  -> Unique clients: 0
   [2021-12-09 22:41:39.004 724M]  -> Known forward destinations: 0

Your gravity database has problems, likely related to your third party script:

   [2021-12-09 22:41:39.018 4826M] Reloading DNS cache
   [2021-12-09 22:41:39.237 4826M] WARN: Found database entries in the future (2021-12-09 22:45:00 (1639107900), last timestamp for importing: 2019-02-14 05:55:00 (1550141700)). Your over-time statistics may be incorrect (found in src/dnsmasq_interface.c:653)
   [2021-12-09 22:41:39.237 4826M] Blocking status is enabled
   [2021-12-09 22:41:39.237 4826M] New upstream server: 127.0.0.1:5335 (0/256)
   [2021-12-09 22:41:39.238 4826M] New upstream server: ::1:5335 (1/256)
   [2021-12-09 22:41:40.068 4826/T4830] Compiled 9 whitelist and 15 blacklist regex filters for 2 clients in 27.9 msec
   [2021-12-09 22:42:16.523 4826M] Reloading DNS cache
   [2021-12-09 22:42:17.490 4826/T4830] SQLite3 message: file renamed while open: /etc/pihole/gravity.db (28)

[willis936]

Here is a debug log after pihole restartdns is run.

https://tricorder.pi-hole.net/aF6NNPUQ/

It looks like the pihole-FTL.conf not only has a lot of overlap with setupVars.conf, but it also has a lot of out-of-date settings. I've culled pihole-FTL.conf to only have AAAA_QUERY_ANALYSIS and PRIVACYLEVEL, as those are not in setupVars.conf.

The third-party script is pihole-updatelists.

https://github.com/jacklul/pihole-updatelists

The time warning is the issue where the system time at boot is 2/14/2019 until chrony initializes.

The writing collision is likely from pihole-updatelists also trying to update gravity. I now have turned off that behavior so it only updates the lists. I'd prefer pihole to manage the gravity database. The behavior is the same after these changes.

Debug log after these changes and a reboot:

https://tricorder.pi-hole.net/hlWBhXm9/

The gravity database collisions are still there so I uninstalled pihole-updatelists. The behavior is the same but it appears that the collision has stopped.

Debug log after this change and a reboot:

https://tricorder.pi-hole.net/jHwMNpC3/

Update: Running a pihole repair and reboot after all of this did not change the behavior.

[willis936]

I did a fresh uinstall / reinstall of pihole, replaced the pihole-FTL.db with the old one, restored settings via teleporter, and still encountered the same issue. I am still using unbound, pihole-updatelists, and https.

https://tricorder.pi-hole.net/sXz3kyxB/

When I start a fresh pihole-FTL.db the behavior goes away. My best guess is that the large database takes too long to initialize and some things time out.

https://tricorder.pi-hole.net/c24EJbYp/

For reference, the pihole-FTL.db I've been building up for the past few years is 4.2 GB.

Edit: My mistake, even with a fresh reinstall of pihole and no pihole-updatelists or https the behavior is still present on reboot until pihole-FTL is restarted. With a fresh db it is faster to get to the point where a pihole-FTL restart fixes the issue.

[willis936]

This was solved by increasing the PHP memory limit in /etc/php/7.3/cgi/php.ini.

[pralor-bot]

This issue has been mentioned on Pi-hole Userspace. There might be relevant details there:

https://discourse.pi-hole.net/t/found-database-entries-in-the-future/55333/2