Even when I toggle "Should FTL store queries in the database?", when the page reloads it's turned off again.
Here are some relevant logs:
1970-01-01 01:00:38.630 CET [1101M] INFO: ########## FTL started on pogo01! ##########
1970-01-01 01:00:38.633 CET [1101M] INFO: FTL branch: tweak/pogo
1970-01-01 01:00:38.634 CET [1101M] INFO: FTL version: v5.25.2-1918-gec6750d4
1970-01-01 01:00:38.634 CET [1101M] INFO: FTL commit: ec6750d4
1970-01-01 01:00:38.634 CET [1101M] INFO: FTL date: 2024-06-10 20:06:41 +0200
1970-01-01 01:00:38.635 CET [1101M] INFO: FTL user: pihole
1970-01-01 01:00:38.635 CET [1101M] INFO: Compiled for armv6l (compiled locally) using cc (Debian 12.2.0-14) 12.2.0
1970-01-01 01:00:38.663 CET [1101M] INFO: Wrote config file:
1970-01-01 01:00:38.663 CET [1101M] INFO: - 136 total entries
1970-01-01 01:00:38.664 CET [1101M] INFO: - 130 entries are default
1970-01-01 01:00:38.664 CET [1101M] INFO: - 6 entries are modified
1970-01-01 01:00:38.666 CET [1101M] INFO: - 0 entries are forced through environment
1970-01-01 01:00:38.700 CET [1101M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
1970-01-01 01:00:38.723 CET [1101M] INFO: PID of FTL process: 1101
1970-01-01 01:00:38.751 CET [1101M] INFO: listening on 0.0.0.0 port 53
1970-01-01 01:00:38.752 CET [1101M] INFO: listening on :: port 53
1970-01-01 01:00:38.783 CET [1106M] INFO: PID of FTL process: 1106
1970-01-01 01:00:38.831 CET [1106M] INFO: Database version is 17
1970-01-01 01:00:38.834 CET [1106M] INFO: Database successfully initialized
1970-01-01 01:00:47.074 CET [1106M] INFO: Imported 27655 queries from the on-disk database (it has 27655 rows)
1970-01-01 01:00:47.075 CET [1106M] INFO: Parsing queries in database
1970-01-01 01:00:48.870 CET [1106M] INFO: Imported 0 queries from the long-term database
1970-01-01 01:00:48.871 CET [1106M] INFO: -> Total DNS queries: 0
1970-01-01 01:00:48.871 CET [1106M] INFO: -> Cached DNS queries: 0
1970-01-01 01:00:48.872 CET [1106M] INFO: -> Forwarded DNS queries: 0
1970-01-01 01:00:48.872 CET [1106M] INFO: -> Blocked DNS queries: 0
1970-01-01 01:00:48.872 CET [1106M] INFO: -> Unknown DNS queries: 0
1970-01-01 01:00:48.873 CET [1106M] INFO: -> Unique domains: 0
1970-01-01 01:00:48.873 CET [1106M] INFO: -> Unique clients: 0
1970-01-01 01:00:48.873 CET [1106M] INFO: -> DNS cache records: 0
1970-01-01 01:00:48.873 CET [1106M] INFO: -> Known forward destinations: 0
1970-01-01 01:00:48.878 CET [1106M] INFO: FTL is running as user pihole (UID 999)
1970-01-01 01:00:48.897 CET [1106M] INFO: Reading certificate from /etc/pihole/tls.pem ...
1970-01-01 01:00:48.899 CET [1106M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
1970-01-01 01:00:48.907 CET [1106M] INFO: Restored 1 API session from the database
1970-01-01 01:00:48.926 CET [1106M] INFO: Blocking status is enabled
1970-01-01 01:00:49.019 CET [1106/T1143] INFO: Compiled 0 allow and 0 deny regex for 1 client in 2.6 msec
2024-06-21 17:24:26.119 CEST [1106/T1143] INFO: Optimized database in 0.118 seconds
2024-06-21 17:24:26.679 CEST [1106M] WARNING: Found database entries in the future (2024-06-21 17:25:00 CEST (1718983500), last timestamp for importing: 1970-01-01 01:05:00 CET (300)). Your over-time statistics may be incorrect (found in src/dnsmasq_interface.c:709)
2024-06-21 17:25:00.231 CEST [1106/T1143] INFO: Size of /etc/pihole/pihole-FTL.db is 1.85 MB, deleted 27 rows
2024-06-22 09:15:48.683 CEST [1106/T1150] INFO: No config changes detected
2024-06-22 09:15:58.862 CEST [1106/T1151] INFO: No config changes detected
2024-06-22 11:50:18.912 CEST [1106/T1148] WARNING: API: Bad request (The API is hosted at pi.hole/api, not pi.hole/admin/api)
2024-06-22 11:50:38.988 CEST [1106/T1148] WARNING: API: Not found (/api)
2024-06-22 11:53:01.908 CEST [1106/T1150] INFO: No config changes detected
2024-06-22 11:53:46.604 CEST [1106/T1148] INFO: No config changes detected
So I think it has something to do with time. When you look closely in the logs, FTL boots in the seventies :D, but after boot ntp should set the date and to the correct values.
After restarting the FTL service, the logs show this:
2024-06-22 12:03:05.038 CEST [6581M] INFO: ########## FTL started on pogo01! ##########
2024-06-22 12:03:05.039 CEST [6581M] INFO: FTL branch: tweak/pogo
2024-06-22 12:03:05.039 CEST [6581M] INFO: FTL version: v5.25.2-1918-gec6750d4
2024-06-22 12:03:05.039 CEST [6581M] INFO: FTL commit: ec6750d4
2024-06-22 12:03:05.040 CEST [6581M] INFO: FTL date: 2024-06-10 20:06:41 +0200
2024-06-22 12:03:05.040 CEST [6581M] INFO: FTL user: pihole
2024-06-22 12:03:05.040 CEST [6581M] INFO: Compiled for armv6l (compiled locally) using cc (Debian 12.2.0-14) 12.2.0
2024-06-22 12:03:05.061 CEST [6581M] INFO: Wrote config file:
2024-06-22 12:03:05.062 CEST [6581M] INFO: - 136 total entries
2024-06-22 12:03:05.062 CEST [6581M] INFO: - 130 entries are default
2024-06-22 12:03:05.062 CEST [6581M] INFO: - 6 entries are modified
2024-06-22 12:03:05.063 CEST [6581M] INFO: - 0 entries are forced through environment
2024-06-22 12:03:05.074 CEST [6581M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-06-22 12:03:05.093 CEST [6581M] INFO: PID of FTL process: 6581
2024-06-22 12:03:05.099 CEST [6581M] INFO: listening on 0.0.0.0 port 53
2024-06-22 12:03:05.100 CEST [6581M] INFO: listening on :: port 53
2024-06-22 12:03:05.120 CEST [6583M] INFO: PID of FTL process: 6583
2024-06-22 12:03:05.140 CEST [6583M] INFO: Database version is 17
2024-06-22 12:03:05.145 CEST [6583M] INFO: Database successfully initialized
2024-06-22 12:03:14.871 CEST [6583M] INFO: Imported 38163 queries from the on-disk database (it has 65818 rows)
2024-06-22 12:03:14.871 CEST [6583M] INFO: Parsing queries in database
2024-06-22 12:03:17.930 CEST [6583M] INFO: 10000 queries parsed...
2024-06-22 12:03:21.811 CEST [6583M] INFO: 20000 queries parsed...
2024-06-22 12:03:24.784 CEST [6583M] INFO: 30000 queries parsed...
2024-06-22 12:03:28.140 CEST [6583M] INFO: Imported 38163 queries from the long-term database
2024-06-22 12:03:28.144 CEST [6583M] INFO: -> Total DNS queries: 38163
2024-06-22 12:03:28.144 CEST [6583M] INFO: -> Cached DNS queries: 9706
2024-06-22 12:03:28.144 CEST [6583M] INFO: -> Forwarded DNS queries: 20690
2024-06-22 12:03:28.145 CEST [6583M] INFO: -> Blocked DNS queries: 7517
2024-06-22 12:03:28.145 CEST [6583M] INFO: -> Unknown DNS queries: 0
2024-06-22 12:03:28.146 CEST [6583M] INFO: -> Unique domains: 1994
2024-06-22 12:03:28.146 CEST [6583M] INFO: -> Unique clients: 3
2024-06-22 12:03:28.146 CEST [6583M] INFO: -> DNS cache records: 3457
2024-06-22 12:03:28.147 CEST [6583M] INFO: -> Known forward destinations: 1
2024-06-22 12:03:28.151 CEST [6583M] INFO: FTL is running as user pihole (UID 999)
2024-06-22 12:03:28.156 CEST [6583M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-06-22 12:03:28.160 CEST [6583M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-06-22 12:03:28.173 CEST [6583M] INFO: Restored 1 API session from the database
2024-06-22 12:03:28.183 CEST [6583M] INFO: Blocking status is enabled
2024-06-22 12:03:28.295 CEST [6583/T6592] INFO: Compiled 0 allow and 0 deny regex for 3 clients in 2.6 msec
Anything I can do to solve this?
I have pihole 5 running on the same hardware and there I don't see this issue
Indeed, your system did not yet sync time when pihole-FTL was started.
Installing a battery-backuped RTC (like the DS3231 mentioned by Moto) would be the most reliable way to address this.
However, I don't think that this is actually possible on Pogoplugs, as they lack any GPIO pins.
You could try to rearrange your system startup sequence, or delay pihole-FTL's startup, hoping that syncing time would have succeeded when it starts.
You may also want to verify if the latter may have been effective for your Pi-hole v5 installation, thus allowing it to pull database queries for the correct timeframe.
In addition, as you are running Debian(? I think you mentioned so in one of your other posts), you could consider to install fake-hwclock.
That package would save your current time to a file on disk periodically (once per hour by default) and on controlled shutdowns, and restore your system time from that file during startup, providing you at least with a consistently forward moving time (somewhat close to your actual time, depending on length of power downs).
I can confirm the use of fake-hwclock for the Pogo's helps a lot as I've always used it since installing Debian on them (I have 6, at least 1 of each of the 4 kinds).
Oh My God I feel so stupid. fake-hwclock is indeed the solution and IIRC was also included in instructions I found a long time ago on how to setup pi-hole on a pogoplug. Thanks guys
Just to put this note here: As precise timing is key to DNSSEC opertions, we have an upcoming change that implements NTP synchronization to Pi-hole itself. This implementation should be able to keep your clock synchronized to the reference clocks within the precision of microseconds (given your local clock isn't drifting too much). Unfortunately, this alone will not solve this issue here because having no time at all at the start of FTL as it will still try to import queries from 1970 during startup even when the clock is synchronized slightly later.
Well, we could do one out of two things actually:
Implement automatic restarting after synchronization. Assume a system starts in 1970. We obviously know that every Pi-hole starting in a year before 2024 these days is wrong. We could trigger an automatic restart after the first successful time synchronization causing FTL to now read the correct history - even without using s third-party tool such as fake-hwclock.[1]
We could have FTL wait until the time is at least something like 2024-01-01 before actually starting. I don't like this idea too much, though - it could easily lead to a deadlock when an NTP client on the machine cannot resolve names so no time synchronization will work.
No. 1 - at least - shouldn't make things worse but it could be useful in a few edge-cases like the Pogoplug and friends.
Given that the NTP server you are using isn't configured for DNSSEC which requires your time to be fairly correct before name resolution will work. pool.ntp.org - for instance - is suitable as it is not doing DNSSEC. âŠī¸
Thank you for your response.
I might be missing something, but if ntp synchronisation is going to be implemented in pi-hole (assuming this is also in pihole-ftl), I think option (2) would be the best option. Because I assume, when FTL starts, it will synchronise time and then continue to start up. I should be able to find an ntp server (via DNS) since the dns configured in /etc/resolv.conf is not the pihole itself but the DNS provided by the ISP or something like 8.8.8.8, 1.1.1.1 ...
No, and that's hitting the nail on its head. From having seen quite some debug logs while helping others, I can confirm that a surprisingly large number of users are using their Pi-hole as the DNS server also on the Pi-hole itself. It's a fair configuration in the end and I use the same configuration on my testing Pi-hole.
This is the main issue I personally have with no. 2 above, sorry for not having made this clear enough.
I did just push a proposed change to our NTP implementation (which is still under review) which will restart FTL when a time offset of more than one hour is detected during NTP synchronization. This seems to be the best mitigation I can come up with right now assuming the system time on the machine FTL runs on may be completely wrong and cannot be trusted.
@DL6ER I see the ntp pull-request got merged which is very nice. Thanks for that. Not sure if this need to be documented somewhere, but I had an ntpsec deamon running on that machine which conflicts with the ntp that is internally started by pihole-FTL. I could see port conflicts on 123 in the logs and I think this prevented pihole-FTL from starting (or at least, nslookups were very slow).
Disabling ntpsec through an rc-update solved the issue.
However, I do see this in the logs (after reboot):
2024-07-01 10:04:31.535 CEST [1119M] INFO: ########## FTL started on pogo01! ##########
2024-07-01 10:04:31.550 CEST [1119M] INFO: FTL branch: development-v6
2024-07-01 10:04:31.550 CEST [1119M] INFO: FTL version: v5.25.2-2003-g1e419022-dirty
2024-07-01 10:04:31.551 CEST [1119M] INFO: FTL commit: 1e419022-dirty
2024-07-01 10:04:31.552 CEST [1119M] INFO: FTL date: 2024-06-30 20:26:00 +0200
2024-07-01 10:04:31.552 CEST [1119M] INFO: FTL user: pihole
2024-07-01 10:04:31.552 CEST [1119M] INFO: Compiled for armv6l (compiled locally) using cc (Debian 12.2.0-14) 12.2.0
2024-07-01 10:04:31.592 CEST [1119M] INFO: Wrote config file:
2024-07-01 10:04:31.593 CEST [1119M] INFO: - 148 total entries
2024-07-01 10:04:31.593 CEST [1119M] INFO: - 142 entries are default
2024-07-01 10:04:31.594 CEST [1119M] INFO: - 6 entries are modified
2024-07-01 10:04:31.594 CEST [1119M] INFO: - 0 entries are forced through environment
2024-07-01 10:04:31.609 CEST [1119M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-07-01 10:04:31.630 CEST [1119M] INFO: PID of FTL process: 1119
2024-07-01 10:04:31.658 CEST [1119M] INFO: listening on 0.0.0.0 port 53
2024-07-01 10:04:31.658 CEST [1119M] INFO: listening on :: port 53
2024-07-01 10:04:31.676 CEST [1123M] INFO: PID of FTL process: 1123
2024-07-01 10:04:31.726 CEST [1123M] INFO: Database version is 18
2024-07-01 10:04:31.728 CEST [1123M] INFO: Database successfully initialized
2024-07-01 10:04:31.809 CEST [1123M] INFO: FTL is running as user pihole (UID 999)
2024-07-01 10:04:31.810 CEST [1123/T1127] INFO: NTP server listening on :::123 (IPv6)
2024-07-01 10:04:31.813 CEST [1123/T1126] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2024-07-01 10:04:31.828 CEST [1123M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-07-01 10:04:31.831 CEST [1123M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-07-01 10:04:33.651 CEST [1123M] INFO: Restored 1 API session from the database
2024-07-01 10:04:33.669 CEST [1123M] INFO: Blocking status is enabled
2024-07-01 10:04:33.760 CEST [1123/T1129] INFO: Compiled 0 allow and 0 deny regex for 0 client in 2.3 msec
2024-07-01 10:04:36.759 CEST [1123/T1128] ERROR: Error NTP client: Cannot resolve NTP server address: Temporary failure in name resolution
2024-07-01 10:04:43.819 CEST [1123/T1128] INFO: Imported 24230 queries from the on-disk database (it has 300372 rows)
2024-07-01 10:04:43.819 CEST [1123/T1128] INFO: Parsing queries in database
2024-07-01 10:04:46.387 CEST [1123/T1128] INFO: 10000 queries parsed...
2024-07-01 10:04:49.645 CEST [1123/T1128] INFO: 20000 queries parsed...
2024-07-01 10:04:51.299 CEST [1123/T1128] INFO: Imported 24243 queries from the long-term database
2024-07-01 10:04:51.299 CEST [1123/T1128] INFO: -> Total DNS queries: 24243
2024-07-01 10:04:51.300 CEST [1123/T1128] INFO: -> Cached DNS queries: 9596
2024-07-01 10:04:51.301 CEST [1123/T1128] INFO: -> Forwarded DNS queries: 10415
2024-07-01 10:04:51.301 CEST [1123/T1128] INFO: -> Blocked DNS queries: 3855
2024-07-01 10:04:51.302 CEST [1123/T1128] INFO: -> Unknown DNS queries: 0
2024-07-01 10:04:51.302 CEST [1123/T1128] INFO: -> Unique domains: 1622
2024-07-01 10:04:51.302 CEST [1123/T1128] INFO: -> Unique clients: 4
2024-07-01 10:04:51.303 CEST [1123/T1128] INFO: -> DNS cache records: 2709
2024-07-01 10:04:51.303 CEST [1123/T1128] INFO: -> Known forward destinations: 1
And time is behind a few minutes ... does the error mean the ntp client did not start and will never start?
DNS server for the pi-hole should be 1.1.1.1 (at least that's what I read in /etc/resolv.conf) and nslookup pool.ntp.org yields results, so not sure where the error is coming from.
This is very surprising. The entire NTP server is handled in a dedicated thread and whether it is available or not does not influence Pi-hole is any way. I wonder if time "behind a few minutes" can already have caused issues upstream with Internet communication?
Can you still reproduce this when re-enabling ntpsec? How do the logs look like in this case?
It will run again based on your settings for the sync interval. The default interval is once per hour so this is most likely what you have as well.
The logs from when the ntpsec server was running, are below:
2024-07-01 09:42:19.667 CEST [3209M] INFO: ########## FTL started on pogo01! ##########
2024-07-01 09:42:19.668 CEST [3209M] INFO: FTL branch: development-v6
2024-07-01 09:42:19.668 CEST [3209M] INFO: FTL version: v5.25.2-2003-g1e419022-dirty
2024-07-01 09:42:19.669 CEST [3209M] INFO: FTL commit: 1e419022-dirty
2024-07-01 09:42:19.669 CEST [3209M] INFO: FTL date: 2024-06-30 20:26:00 +0200
2024-07-01 09:42:19.669 CEST [3209M] INFO: FTL user: pihole
2024-07-01 09:42:19.670 CEST [3209M] INFO: Compiled for armv6l (compiled locally) using cc (Debian 12.2.0-14) 12.2.0
2024-07-01 09:42:19.697 CEST [3209M] INFO: Wrote config file:
2024-07-01 09:42:19.697 CEST [3209M] INFO: - 148 total entries
2024-07-01 09:42:19.697 CEST [3209M] INFO: - 142 entries are default
2024-07-01 09:42:19.698 CEST [3209M] INFO: - 6 entries are modified
2024-07-01 09:42:19.698 CEST [3209M] INFO: - 0 entries are forced through environment
2024-07-01 09:42:19.709 CEST [3209M] INFO: Config file written to /etc/pihole/pihole.toml
2024-07-01 09:42:19.719 CEST [3209M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-07-01 09:42:19.740 CEST [3209M] INFO: PID of FTL process: 3209
2024-07-01 09:42:19.752 CEST [3209M] INFO: listening on 0.0.0.0 port 53
2024-07-01 09:42:19.752 CEST [3209M] INFO: listening on :: port 53
2024-07-01 09:42:19.778 CEST [3211M] INFO: PID of FTL process: 3211
2024-07-01 09:42:19.831 CEST [3211M] INFO: Database version is 17
2024-07-01 09:42:19.832 CEST [3211M] INFO: Updating long-term database to version 18
2024-07-01 09:42:19.890 CEST [3211M] INFO: Database successfully initialized
2024-07-01 09:42:19.945 CEST [3211/T3215] ERROR: Error NTP server: Cannot bind to IPv4 address 0.0.0.0:123 (Address already in use), IPv4 NTP server not available
2024-07-01 09:42:19.948 CEST [3211M] INFO: FTL is running as user pihole (UID 999)
2024-07-01 09:42:19.951 CEST [3211/T3216] ERROR: Error NTP server: Cannot bind to IPv6 address :::123 (Address already in use), IPv6 NTP server not available
2024-07-01 09:42:19.963 CEST [3211M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-07-01 09:42:19.965 CEST [3211M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-07-01 09:42:19.975 CEST [3211M] INFO: Restored 0 API sessions from the database
2024-07-01 09:42:19.007 CEST [3211M] INFO: Blocking status is enabled
2024-07-01 09:42:20.086 CEST [3211/T3218] INFO: Compiled 0 allow and 0 deny regex for 0 client in 2.3 msec
2024-07-01 09:42:24.168 CEST [3211/T3217] INFO: Received 8/8 valid NTP replies from pool.ntp.org
2024-07-01 09:42:24.169 CEST [3211/T3217] INFO: Time offset: -1.692568e+00 ms (excluded 1 outliers)
2024-07-01 09:42:24.169 CEST [3211/T3217] INFO: Round-trip delay: 1.714979e+01 ms (excluded 1 outliers)
2024-07-01 09:42:32.232 CEST [3211/T3217] INFO: Imported 25770 queries from the on-disk database (it has 300347 rows)
2024-07-01 09:42:32.232 CEST [3211/T3217] INFO: Parsing queries in database
2024-07-01 09:42:35.155 CEST [3211/T3217] INFO: 10000 queries parsed...
2024-07-01 09:42:38.287 CEST [3211/T3217] INFO: 20000 queries parsed...
2024-07-01 09:42:40.649 CEST [3211/T3217] INFO: Imported 25753 queries from the long-term database
2024-07-01 09:42:40.670 CEST [3211/T3217] INFO: -> Total DNS queries: 25753
2024-07-01 09:42:40.672 CEST [3211/T3217] INFO: -> Cached DNS queries: 10003
2024-07-01 09:42:40.672 CEST [3211/T3217] INFO: -> Forwarded DNS queries: 11123
2024-07-01 09:42:40.673 CEST [3211/T3217] INFO: -> Blocked DNS queries: 4203
2024-07-01 09:42:40.674 CEST [3211/T3217] INFO: -> Unknown DNS queries: 1
2024-07-01 09:42:40.675 CEST [3211/T3217] INFO: -> Unique domains: 1706
2024-07-01 09:42:40.696 CEST [3211/T3217] INFO: -> Unique clients: 4
2024-07-01 09:42:40.699 CEST [3211/T3217] INFO: -> DNS cache records: 2857
2024-07-01 09:42:40.700 CEST [3211/T3217] INFO: -> Known forward destinations: 1
So I guess FTL was still running, but it seemed slow.
Time is indeed correct now, ntp query restarted after an hour, so indeed, you are correct.
I cannot confirm/reproduce this in any way. Maybe you can switch on debug.queries = true in /etc/pihole/pihole.toml and monitor the log file to see if there are really some measurable delays in responding once with the other NTP server enabled and once not.
Sorry for the late reply. I am running latest version and pulling weekly from main develop-v6 branch.
All seems to work fine now and I have not revisited this issue with ntp running at the same time. If it's ok for you, let's skip this for the time being. After all I am running on some pretty exotic hardware, so I don't think my use case is very representative.
I feel so stupid. 