Pi-hole is running
Since my update to v5 three days ago it shows „lost connection to api“ once or twice a day. DNS Service and FTL in Status are red. After rebooting the raspberry pi it runs until the next crash.
You got some errors in your debug log.
2021-05-15 06:57:00.540 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 06:57:00.540 624/T628] Message: Success
[2021-05-15 06:58:00.675 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 06:58:00.675 624/T628] Message: Success
[2021-05-15 06:59:00.785 624/T628] Notice: Database size is 31.22 MB, deleted 5 rows
[2021-05-15 06:59:00.785 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 06:59:00.785 624/T628] Message: Success
[2021-05-15 07:00:00.892 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:00:00.892 624/T628] Message: Success
[2021-05-15 07:01:01.000 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:01:01.000 624/T628] Message: Success
[2021-05-15 07:02:00.101 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:02:00.101 624/T628] Message: Success
[2021-05-15 07:03:00.176 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:03:00.176 624/T628] Message: Success
[2021-05-15 07:04:00.280 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:04:00.280 624/T628] Message: Success
[2021-05-15 07:05:00.381 624/T628] WARN: Command "ip neigh show" failed!
[2021-05-15 07:05:00.381 624/T628] Message: Success
What's the output of
ip neigh show
192.168.178.25 dev eth0 lladdr 4c:0b:be:9d:24:01 STALE
192.168.178.43 dev eth0 lladdr 6a:c1:3d:90:22:11 REACHABLE
192.168.178.1 dev eth0 lladdr c8:0e:14:1d:19:1c REACHABLE
fe80::ca0e:14ff:fe1d:191c dev eth0 lladdr c8:0e:14:1d:19:1c router REACHABLE
It happened again just a moment ago.
Here’s a fresh debug log and the current output of ip neigh show
https://tricorder.pi-hole.net/eorkwnrgjo
192.168.178.25 dev eth0 lladdr 4c:0b:be:9d:24:01 STALE
192.168.178.43 dev eth0 lladdr 6a:c1:3d:90:22:11 REACHABLE
192.168.178.35 dev eth0 lladdr 18:65:90:e0:e9:23 STALE
192.168.178.1 dev eth0 lladdr c8:0e:14:1d:19:1c REACHABLE
192.168.178.37 dev eth0 lladdr 24:65:11:df:7a:0a STALE
2001:4dd7:6761:0:4939:efa0:2254:a3e6 dev eth0 lladdr 18:65:90:e0:e9:23 STALE
fe80::ca0e:14ff:fe1d:191c dev eth0 lladdr c8:0e:14:1d:19:1c router REACHABLE
fe80::886:3945:e1c2:1249 dev eth0 lladdr 18:65:90:e0:e9:23 STALE
According to the source code this happens here:
The test is against NULL, the description of popen() says:
popen(): on success, returns a pointer to an open stream that can be used to read or write to the pipe; if the fork(2) or pipe(2) calls fail, or if the function cannot allocate memory, NULL is returned.
The combination with your
supports the idea of failed memory allocation as the documentation continues as:
The popen() function does not set errno if memory allocation fails. If the underlying fork(2) or pipe(2) fails, errno is set appropriately. If the type argument is invalid, and this condition is detected, errno is set to EINVAL.
So the question is really: Why did memory allocation fail for you? Are you exhausting memory to the limit? I wonder why there aren't more warnings/error messages in your log file but this is surely the reason for why other things don't work as well.
@DL6ER please have a look.
What is the output of
free
after a reboot and what is it when you see the issue?
At the moment this is the Output of free:
total used free shared buff/cache available
Mem: 948300 76124 676252 11456 195924 807116
Swap: 102396 0 102396
There is only pihole and cups running on this pi.
I will post an update after the next incident.
Your new debug log contains a few lines of /var/log/pihole-FTL.log with only the IP neigh messages. Could you checker the log manually for other suspicious entries or errors?
There are a lot entries for SQLite3 like
[2021-05-17 05:46:00.797 625/T629] SQLite3 message: index corruption at line 91877 of [5d4c65779d] (779)
[2021-05-17 05:46:00.797 625/T629] SQLite3 message: statement aborts at 25: [DELETE FROM network_addresses WHERE lastSeen < 1589690760;] database disk image is malformed (779)
[2021-05-17 05:46:00.797 625/T629] ERROR: SQL query "DELETE FROM network_addresses WHERE lastSeen < 1589690760;" failed: database disk image is malformed
[2021-05-17 05:46:00.798 625/T629] SQLite3 message: API call with invalid database connection pointer (21)
[2021-05-17 05:46:00.798 625/T629] SQLite3 message: misuse at line 165242 of [5d4c65779d] (21)
[2021-05-17 05:46:00.798 625/T629] Error while trying to close database: bad parameter or other API misuse
[2021-05-17 05:47:04.859 625/T629] SQLite3 message: index corruption at line 91877 of [5d4c65779d] (779)
[2021-05-17 05:47:04.859 625/T629] SQLite3 message: statement aborts at 25: [DELETE FROM network_addresses WHERE lastSeen < 1589690824;] database disk image is malformed (779)
[2021-05-17 05:47:04.859 625/T629] ERROR: SQL query "DELETE FROM network_addresses WHERE lastSeen < 1589690824;" failed: database disk image is malformed
or
[2021-05-17 12:49:00.527 625/T629] SQLite3 message: index corruption at line 91877 of [5d4c65779d] (779)
[2021-05-17 12:49:00.527 625/T629] SQLite3 message: statement aborts at 25: [DELETE FROM network_addresses WHERE lastSeen < 1589716140;] database disk image is malformed (779)
[2021-05-17 12:49:00.527 625/T629] ERROR: SQL query "DELETE FROM network_addresses WHERE lastSeen < 1589716140;" failed: database disk image is malformed
[2021-05-17 12:49:00.527 625/T629] SQLite3 message: API call with invalid database connection pointer (21)
[2021-05-17 12:49:00.528 625/T629] SQLite3 message: misuse at line 165242 of [5d4c65779d] (21)
[2021-05-17 12:49:00.528 625/T629] Error while trying to close database: bad parameter or other API misuse
This is bad. Your database file on disk reports some corruption in the index. A quick google around shows a few similar cases (outside of Pi-hole) but no solution wherever I looked. Is there more information above this line?
There is a database recovery method baked into FTL, I've seen somewhere here. You may want to try this.
But, overall, it seems there are more things wrong on your system. If they come from the same origin or are bad luck is something I cannot answer at this time.
Found the recovery procedure here:
Thanks @Coro
these are the entries above the database errrors.
A lot of lines with
[2021-05-17 04:58:00.774 626/T630] WARN: Command "ip neigh show" failed!
[2021-05-17 04:58:00.774 626/T630] Message: Success
interrupted by this after every 40-50 warning, with different count for deleted rows
[2021-05-17 04:59:00.891 626/T630] Notice: Database size is 33.22 MB, deleted 263 rows
and then
[2021-05-17 05:45:56.946 619M] Using log file /var/log/pihole-FTL.log
[2021-05-17 05:45:56.947 619M] ########## FTL started! ##########
[2021-05-17 05:45:56.947 619M] FTL branch: master
[2021-05-17 05:45:56.947 619M] FTL version: v5.8.1
[2021-05-17 05:45:56.947 619M] FTL commit: b90ab8b1
[2021-05-17 05:45:56.947 619M] FTL date: 2021-04-21 20:03:47 +0100
[2021-05-17 05:45:56.947 619M] FTL user: pihole
[2021-05-17 05:45:56.947 619M] Compiled for armv7hf (compiled on CI) using arm-linux-gnueabihf-gcc (Debian 6.3.0-18) 6.3.0 20170516
[2021-05-17 05:45:56.947 619M] Creating mutex
[2021-05-17 05:45:56.949 619M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2021-05-17 05:45:56.949 619M] SOCKET_LISTENING: only local
[2021-05-17 05:45:56.949 619M] AAAA_QUERY_ANALYSIS: Show AAAA queries
[2021-05-17 05:45:56.949 619M] MAXDBDAYS: max age for stored queries is 365 days
[2021-05-17 05:45:56.949 619M] RESOLVE_IPV6: Resolve IPv6 addresses
[2021-05-17 05:45:56.949 619M] RESOLVE_IPV4: Resolve IPv4 addresses
[2021-05-17 05:45:56.949 619M] DBINTERVAL: saving to DB file every minute
[2021-05-17 05:45:56.949 619M] DBFILE: Using /etc/pihole/pihole-FTL.db
[2021-05-17 05:45:56.949 619M] MAXLOGAGE: Importing up to 24.0 hours of log data
[2021-05-17 05:45:56.949 619M] PRIVACYLEVEL: Set to 0
[2021-05-17 05:45:56.949 619M] IGNORE_LOCALHOST: Show queries from localhost
[2021-05-17 05:45:56.950 619M] BLOCKINGMODE: Null IPs for blocked domains
[2021-05-17 05:45:56.950 619M] ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2021-05-17 05:45:56.950 619M] DBIMPORT: Importing history from database
[2021-05-17 05:45:56.950 619M] PIDFILE: Using /run/pihole-FTL.pid
[2021-05-17 05:45:56.950 619M] PORTFILE: Using /run/pihole-FTL.port
[2021-05-17 05:45:56.950 619M] SOCKETFILE: Using /run/pihole/FTL.sock
[2021-05-17 05:45:56.950 619M] SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2021-05-17 05:45:56.950 619M] MACVENDORDB: Using /etc/pihole/macvendor.db
[2021-05-17 05:45:56.950 619M] GRAVITYDB: Using /etc/pihole/gravity.db
[2021-05-17 05:45:56.950 619M] PARSE_ARP_CACHE: Active
[2021-05-17 05:45:56.950 619M] CNAME_DEEP_INSPECT: Active
[2021-05-17 05:45:56.950 619M] DELAY_STARTUP: No delay requested.
[2021-05-17 05:45:56.950 619M] BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
[2021-05-17 05:45:56.950 619M] NICE: Set process niceness to -10 (default)
[2021-05-17 05:45:56.950 619M] MAXNETAGE: Removing IP addresses and host names from network table after 365 days
[2021-05-17 05:45:56.950 619M] NAMES_FROM_NETDB: Enabled, trying to get names from network database
[2021-05-17 05:45:56.950 619M] EDNS0_ECS: Overwrite client from ECS information
[2021-05-17 05:45:56.950 619M] REFRESH_HOSTNAMES: Periodically refreshing IPv4 names
[2021-05-17 05:45:56.950 619M] RATE_LIMIT: Rate-limiting client making more than 1000 queries in 60 seconds
[2021-05-17 05:45:56.950 619M] REPLY_ADDR4: Automatic interface-dependent detection of address
[2021-05-17 05:45:56.951 619M] REPLY_ADDR6: Automatic interface-dependent detection of address
[2021-05-17 05:45:56.951 619M] Finished config file parsing
[2021-05-17 05:45:56.955 619M] Database version is 9
[2021-05-17 05:45:56.955 619M] Imported 0 alias-clients
[2021-05-17 05:45:56.956 619M] Database successfully initialized
[2021-05-17 05:45:56.962 619M] Resizing "FTL-strings" from 40960 to (81920 * 1) == 81920 (/dev/shm: 1.0MB used, 485.5MB total, FTL uses 1.0MB)
[2021-05-17 05:45:56.962 619M] New upstream server: 8.8.4.4:53 (0/1024)
[2021-05-17 05:45:56.971 619M] New upstream server: 2001:4860:4860::8844:53 (1/1024)
[2021-05-17 05:45:56.983 619M] Resizing "FTL-domains" from 4096 to (512 * 16) == 8192 (/dev/shm: 1.1MB used, 485.5MB total, FTL uses 1.0MB)
[2021-05-17 05:45:57.000 619M] New upstream server: 2001:4860:4860::8888:53 (2/1024)
[2021-05-17 05:45:57.031 619M] New upstream server: 8.8.8.8:53 (3/1024)
[2021-05-17 05:45:57.040 619M] Resizing "FTL-domains" from 8192 to (768 * 16) == 12288 (/dev/shm: 1.1MB used, 485.5MB total, FTL uses 1.1MB)
[2021-05-17 05:45:57.065 619M] Resizing "FTL-queries" from 229376 to (8192 * 56) == 458752 (/dev/shm: 1.1MB used, 485.5MB total, FTL uses 1.1MB)
[2021-05-17 05:45:57.163 619M] Resizing "FTL-domains" from 12288 to (1024 * 16) == 16384 (/dev/shm: 1.3MB used, 485.5MB total, FTL uses 1.3MB)
[2021-05-17 05:45:57.174 619M] Resizing "FTL-queries" from 458752 to (12288 * 56) == 688128 (/dev/shm: 1.3MB used, 485.5MB total, FTL uses 1.3MB)
[2021-05-17 05:45:57.294 619M] Resizing "FTL-queries" from 688128 to (16384 * 56) == 917504 (/dev/shm: 1.5MB used, 485.5MB total, FTL uses 1.5MB)
[2021-05-17 05:45:57.313 619M] Resizing "FTL-domains" from 16384 to (1280 * 16) == 20480 (/dev/shm: 1.8MB used, 485.5MB total, FTL uses 1.7MB)
[2021-05-17 05:45:57.408 619M] Resizing "FTL-queries" from 917504 to (20480 * 56) == 1146880 (/dev/shm: 1.8MB used, 485.5MB total, FTL uses 1.8MB)
[2021-05-17 05:45:57.552 619M] Resizing "FTL-queries" from 1146880 to (24576 * 56) == 1376256 (/dev/shm: 2.0MB used, 485.5MB total, FTL uses 2.0MB)
[2021-05-17 05:45:57.571 619M] Resizing "FTL-domains" from 20480 to (1536 * 16) == 24576 (/dev/shm: 2.2MB used, 485.5MB total, FTL uses 2.2MB)
[2021-05-17 05:45:57.671 619M] Resizing "FTL-queries" from 1376256 to (28672 * 56) == 1605632 (/dev/shm: 2.2MB used, 485.5MB total, FTL uses 2.2MB)
[2021-05-17 05:45:57.729 619M] Imported 26405 queries from the long-term database
[2021-05-17 05:45:57.730 619M] -> Total DNS queries: 26405
[2021-05-17 05:45:57.731 619M] -> Cached DNS queries: 4622
[2021-05-17 05:45:57.731 619M] -> Forwarded DNS queries: 20204
[2021-05-17 05:45:57.731 619M] -> Blocked DNS queries: 1255
[2021-05-17 05:45:57.731 619M] -> Unknown DNS queries: 0
[2021-05-17 05:45:57.731 619M] -> Unique domains: 1347
[2021-05-17 05:45:57.731 619M] -> Unique clients: 3
[2021-05-17 05:45:57.731 619M] -> Known forward destinations: 4
[2021-05-17 05:45:57.731 619M] Successfully accessed setupVars.conf
[2021-05-17 05:45:57.737 625M] PID of FTL process: 625
[2021-05-17 05:45:57.738 625/T626] Listening on port 4711 for incoming IPv4 telnet connections
[2021-05-17 05:45:57.738 625M] INFO: FTL is running as user pihole (UID 999)
[2021-05-17 05:45:57.739 625/T627] Listening on port 4711 for incoming IPv6 telnet connections
[2021-05-17 05:45:57.739 625/T628] Listening on Unix socket
[2021-05-17 05:45:57.740 625M] Reloading DNS cache
[2021-05-17 05:45:57.740 625M] Blocking status is enabled
[2021-05-17 05:45:57.762 625/T629] Compiled 0 whitelist and 0 blacklist regex filters for 3 clients in 2.0 msec
[2021-05-17 05:46:00.797 625/T629] SQLite3 message: index corruption at line 91877 of [5d4c65779d] (779)
I tried the recovery procedure but I'm not shure if it worked properly. There were a lot of errors like
Error: near line 329155: UNIQUE constraint failed: queries.id
and
Error: near line 329156: NOT NULL constraint failed: queries.status
when iI did pihole-FTL /etc/pihole/pihole-FTL.db ".recover" | pihole-FTL ~/pihole-FTL_recovered.db
What would be the ultimate solution? Deleting the database by removing /etc/pihole/pihole-FTL.db?
Yes.
Make sure to stop pihole-FTL before.
database disk image is malformed usually points to file system errors which can occur near EOL of SD cards or sudden power failures due to insufficient power supplies. This might be a good time to check the power supply, re-flash the whole SD card or exchange it completely.
Thanks for the hint. I couldn't identify this as a root of the problem for now. There is no SD Card. The pi is booting from an external SSD. A check with smartctl showed no problems.
The pi is also fed with a 2500mA power supply. This should be enough.
The good news is that I had no problems since I did the recovery process. Even the log shows no database problems and no more "ip neigh show" failed since then.
But at least due to your help I now know where to look if it should happen again. Thanks a lot.
Yes
sudo service pihole-FTL stop
sudo rm /etc/pihole/pihole-FTL.db
sudo service pihole-FTL start
is the nuclear option that will always work.
Thank you, Coro
There is still no more incident here. I think, the database corruption was caused by a power failure a while ago.
This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.