New update FTL 5.5 / FATAL: Trying to access upstream ID -1, but maximum is 1024 / pihole-FTL.log ERRORS

Max-Mustermann · January 19, 2021, 1:20pm

after emergency update due to dnsmask security issues pihole-FTL.log shows
following errors:

[2021-01-19 13:59:00.628 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.628 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.628 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.628 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.628 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.628 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.628 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.628 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.628 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.629 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.629 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.629 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.629 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.629 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)

is it due to updating process?

[2021-01-19 13:59:00.633 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.633 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.633 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.633 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.633 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.634 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.634 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 13:59:00.634 21462/T21467] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 13:59:00.634 21462/T21467] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:00:00.413 21462/T21466] Notice: Database size is 359.67 MB, deleted 4874 rows
[2021-01-19 14:08:39.120 21462M] Reloading DNS cache
[2021-01-19 14:08:39.173 21462M] Blocking status is enabled
[2021-01-19 14:08:39.275 21462/T21466] SQLite3 message: file unlinked while open: /etc/pihole/gravity.db (28)
[2021-01-19 14:08:39.408 21462/T21466] Compiled 19 whitelist and 104 blacklist regex filters for 18 clients in 100.6 msec
[2021-01-19 14:11:35.059 21462M] Resizing "FTL-strings" from 36864 to (40960 * 1) == 40960 (/dev/shm: 4.4MB used, 484.9MB total)
[2021-01-19 14:14:34.635 21462M] Resizing "FTL-dns-cache" from 12288 to (1024 * 16) == 16384 (/dev/shm: 4.4MB used, 484.9MB total)
[2021-01-19 14:21:32.198 21462M] Shutting down...
[2021-01-19 14:21:33.555 21462M] Finished final database update
[2021-01-19 14:21:33.567 21462M] ########## FTL terminated after 37m 46s ! ##########
[2021-01-19 14:22:10.373 594M] ########## FTL started! ##########
[2021-01-19 14:22:10.373 594M] FTL branch: master
[2021-01-19 14:22:10.373 594M] FTL version: v5.5
[2021-01-19 14:22:10.373 594M] FTL commit: fb9b274
[2021-01-19 14:22:10.373 594M] FTL date: 2021-01-19 13:17:26 +0100
[2021-01-19 14:22:10.373 594M] FTL user: pihole
[2021-01-19 14:22:10.373 594M] Compiled for armv7hf (compiled on CI) using arm-linux-gnueabihf-gcc (Debian 6.3.0-18) 6

jpgpi250 · January 19, 2021, 1:35pm

Same error here, thus confirmed problem

Max-Mustermann · January 19, 2021, 2:31pm

NO, not during update process - persistant ERROR:

[2021-01-19 14:59:01.033 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.033 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.033 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.033 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.034 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.034 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.034 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.034 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.034 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.034 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.034 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.035 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.035 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.035 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.035 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.035 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.035 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.035 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.035 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.036 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.036 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.036 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.036 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 14:59:01.037 645/T650] FATAL: Trying to access upstream ID -1, but maximum is 1024
[2021-01-19 14:59:01.037 645/T650] found in GC_thread() (/root/project/src/gc.c:92)
[2021-01-19 15:00:00.452 645/T649] Notice: Database size is 359.67 MB, deleted 4293 rows
[2021-01-19 15:03:53.544 645M] Resizing "FTL-dns-cache" from 16384 to (1280 * 16) == 20480 (/dev/shm: 4.5MB used, 484.9MB total)
[2021-01-19 15:21:21.057 645M] Resizing "FTL-dns-cache" from 20480 to (1536 * 16) == 24576 (/dev/shm: 4.5MB used, 484.9MB total)

DL6ER · January 19, 2021, 2:44pm

Thanks for the report. This is a regression from

github.com/pi-hole/FTL

Fix for Query Log filtering and memory optimizations

pi-hole:development ← pi-hole:fix/querylog_filtering

opened 02:35PM - 18 Jan 21 UTC

DL6ER

+205 -158

**By submitting this pull request, I confirm the following:** - [X] I have re…ad and understood the [contributors guide](https://github.com/pi-hole/pi-hole/blob/master/CONTRIBUTING.md). - [X] I have checked that [another pull request](https://github.com/pi-hole/FTL/pulls) for this purpose does not exist. - [X] I have considered, and confirmed that this submission will be valuable to others. - [X] I accept that this submission may not be used, and the pull request closed at the will of the maintainer. - [X] I give this submission freely, and claim no ownership to its content. **How familiar are you with the codebase?:** ## 10 --- This PR fixes https://github.com/pi-hole/FTL/issues/1026 and https://github.com/pi-hole/FTL/issues/1027 by ensuring the first upstream destination is not a collector for all kinds of other queries. There was an ill assumption in the API code leading to a (much) too loose filtering. Furthermore, I added a bitfield to the `queriesData` struct to allow further simplification of the API code easing future maintainability (the same code will go into v6.0 so this still matters). While at it, I added a mechanism to ensure the size of memory objects does not change without us noticing (the CI will fail). The first commit optimized the internal datastructure FTL uses. By this, we were able to save 8 bytes of memory per query, oer client and per regex. On a typical setup with some clients, some regex and about 25,000 queries per day, this means a memory usage reduction of roughly 0.2 MB. This continues our efforts to fit Pi-hole into the smallest possible memory footprint (v5.0 already drastically reduced memory footprint due to using a B-tree for the blocking domains).

and can be safely ignored. However, I see it may be creating a flood of messages so we're going to get this fixed as soon as possible.

Max-Mustermann · January 19, 2021, 2:46pm

Thanks, u saved me from applying my last backup (which is 3 days old)

DL6ER · January 19, 2021, 2:49pm

For now you can run

pihole checkout ftl fix/incorrect_GC_error

to get this patched (may take a few minutes until it is ready, Github is currently experiencing degraded performance). We're working on bringing the patch out as soon as possible.

Max-Mustermann · January 19, 2021, 2:52pm

waiting for the "regular" fix via 'pihole -up', ur statement "... and can be safely ignored" is fine for me (as it is not affecting correct working but only generating lot of logs) - FATAL gave me some concerns

DL6ER · January 19, 2021, 3:14pm

Pi-hole FTL v5.5.1 is up and ready.

Max-Mustermann · January 19, 2021, 3:15pm

will test and come back

jpgpi250 · January 19, 2021, 3:18pm

pihole-FTL -vv
****************************** FTL **********************************
Version:         vDev-92ea5db

****************************** dnsmasq ******************************
Version:         pi-hole-2.83
Compile options: IPv6 GNU-getopt no-DBus no-UBus no-i18n IDN DHCP DHCPv6 Lua TFTP no-conntrack ipset auth nettlehash DNSSEC loop-detect inotify dumpfile

****************************** SQLite3 ******************************
Version:         3.34.0
Compile options: COMPILER=gcc-6.3.0 20170516 DEFAULT_FOREIGN_KEYS OMIT_DEPRECATED OMIT_LOAD_EXTENSION OMIT_PROGRESS_CALLBACK THREADSAFE=1
******************************** LUA ********************************
Lua 5.4.1  Copyright (C) 1994-2020 Lua.org, PUC-Rio

Startup apparently without errors

Quick Fix, thank you

edit
just received github notification for pihole-FTL 5.5.1
/edit

Thank you for the quick fix, your time and effort

jpgpi250 · January 19, 2021, 3:32pm

upgraded to 5.5.1 (pihole checkout ftl master)

error messages immediately after startup, never seen before, errors do NOT repeat (for now)

[2021-01-19 16:24:03.332 28550/T28554] Compiled 3 whitelist and 39 blacklist regex filters for 11 clients in 21.0 msec
[2021-01-19 16:24:04.978 28550M] domain_in_list("166.2.168.192.in-addr.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.979 28550M] domain_in_list("100.2.168.192.in-addr.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.980 28550M] domain_in_list("228.2.168.192.in-addr.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.981 28550M] domain_in_list("a.7.e.0.4.6.9.2.c.1.d.c.8.6.0.c.3.0.9.6.2.0.d.4.0.1.8.1.2.0.a.2.ip6.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.982 28550M] domain_in_list("1.9.9.7.0.a.d.4.c.4.7.c.a.8.0.7.3.0.9.6.2.0.d.4.0.1.8.1.2.0.a.2.ip6.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.982 28550M] domain_in_list("227.2.168.192.in-addr.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.983 28550M] domain_in_list("4.7.5.3.9.0.e.0.4.2.c.3.0.0.d.3.3.0.9.6.2.0.d.4.0.1.8.1.2.0.a.2.ip6.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.984 28550M] domain_in_list("249.2.168.192.in-addr.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:24:04.985 28550M] domain_in_list("d.8.d.a.3.2.8.e.3.b.a.a.8.9.6.b.3.0.9.6.2.0.d.4.0.1.8.1.2.0.a.2.ip6.arpa", 0x7372c2e8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.427 28550M] domain_in_list("cdn2.ghostery.com", 0x73728f58, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.427 28550M] domain_in_list("cdn2.ghostery.com", 0x73728aa8, blacklist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.427 28550M] domain_in_list("cdn2.ghostery.com", 0x73728148, gravity): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.428 28550M] domain_in_list("cdn2.ghostery.com", 0x73728f58, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.428 28550M] domain_in_list("cdn2.ghostery.com", 0x73728aa8, blacklist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:25:01.429 28550M] domain_in_list("cdn2.ghostery.com", 0x73728148, gravity): Database is busy, assuming domain is NOT on list
[2021-01-19 16:27:11.481 28550M] Resizing "FTL-strings" from 12288 to (16384 * 1) == 16384 (/dev/shm: 970.8KB used, 484.9MB total)

Max-Mustermann · January 19, 2021, 3:45pm

Confirmed from my side also, pihole-FTL.log is clean with regards to that error - thanks a ton!
Was a lightning fix

Max-Mustermann · January 19, 2021, 3:49pm

[2021-01-19 16:16:33.850 16793M] domain_in_list("detectportal.firefox.com", 0x73228aa8, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:16:33.851 16793M] domain_in_list("detectportal.firefox.com", 0x73229408, blacklist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:16:33.851 16793M] domain_in_list("detectportal.firefox.com", 0x73228148, gravity): Database is busy, assuming domain is NOT on list

guess this is due to startup of DB and in parallel getting requests ?!??!

jpgpi250 · January 19, 2021, 3:55pm

fresh install, running SQL script to populate database (groups, clients, domains). Never had any problems with this. Now the log is filled with errors:

[2021-01-19 16:44:04.195 11896/T11897] Listening on port 4711 for incoming IPv4 telnet connections
[2021-01-19 16:44:04.196 11896/T11899] Listening on Unix socket
[2021-01-19 16:44:04.196 11896M] INFO: FTL is running as user pihole (UID 999)
[2021-01-19 16:44:04.196 11896/T11898] Listening on port 4711 for incoming IPv6 telnet connections
[2021-01-19 16:44:04.197 11896M] Reloading DNS cache
[2021-01-19 16:44:04.199 11896M] Blocking status is enabled
[2021-01-19 16:44:04.321 11896/T11900] Compiled 0 whitelist and 0 blacklist regex filters for 3 clients in 0.7 msec
[2021-01-19 16:44:10.298 11896M] New upstream server: 127.10.10.2:5552 (1/1024)
[2021-01-19 16:44:11.837 11896M] New upstream server: 208.67.220.220:53 (2/1024)
[2021-01-19 16:45:59.806 11896M] Received: Real-time signal 4 (38 -> 4)
[2021-01-19 16:49:31.111 11896M] Received: Real-time signal 0 (34 -> 0)
[2021-01-19 16:49:31.195 11896/T11900] get_client_groupids("192.168.2.227", "hp7900.localdomain") - SQL error step: database is locked
[2021-01-19 16:49:31.195 11896/T11900] get_client_groupids("127.0.0.1") - SQL error step: database is locked
[2021-01-19 16:49:31.196 11896/T11900] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:49:31.196 11896/T11900] get_client_groupids("192.168.2.166") - SQL error step: database is locked
[2021-01-19 16:49:31.196 11896/T11900] Compiled 0 whitelist and 38 blacklist regex filters for 4 clients in 7.5 msec
[2021-01-19 16:49:35.823 11896M] Received: Real-time signal 0 (34 -> 0)
[2021-01-19 16:49:35.966 11896/T11900] Compiled 3 whitelist and 39 blacklist regex filters for 4 clients in 12.1 msec
[2021-01-19 16:49:39.750 11896M] Shutting down...
[2021-01-19 16:49:39.795 11896M] Finished final database update
[2021-01-19 16:49:39.796 11896M] ########## FTL terminated after 5m 35s ! ##########
[2021-01-19 16:49:44.719 21969M] ########## FTL started! ##########
[2021-01-19 16:49:44.719 21969M] FTL branch: master
[2021-01-19 16:49:44.719 21969M] FTL version: v5.5.1
[2021-01-19 16:49:44.719 21969M] FTL commit: 3ecec15
[2021-01-19 16:49:44.719 21969M] FTL date: 2021-01-19 15:56:18 +0100
[2021-01-19 16:49:44.719 21969M] FTL user: pihole
[2021-01-19 16:49:44.719 21969M] Compiled for armv7hf (compiled on CI) using arm-linux-gnueabihf-gcc (Debian 6.3.0-18) 6.3.0 20170516
[2021-01-19 16:49:44.720 21969M] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2021-01-19 16:49:44.720 21969M]    SOCKET_LISTENING: only local
[2021-01-19 16:49:44.720 21969M]    AAAA_QUERY_ANALYSIS: Show AAAA queries
[2021-01-19 16:49:44.720 21969M]    MAXDBDAYS: max age for stored queries is 8 days
[2021-01-19 16:49:44.720 21969M]    RESOLVE_IPV6: Resolve IPv6 addresses
[2021-01-19 16:49:44.721 21969M]    RESOLVE_IPV4: Resolve IPv4 addresses
[2021-01-19 16:49:44.721 21969M]    DBINTERVAL: saving to DB file every 120 seconds
[2021-01-19 16:49:44.721 21969M]    DBFILE: Using /etc/pihole/pihole-FTL.db
[2021-01-19 16:49:44.721 21969M]    MAXLOGAGE: Importing up to 24.0 hours of log data
[2021-01-19 16:49:44.721 21969M]    PRIVACYLEVEL: Set to 0
[2021-01-19 16:49:44.722 21969M]    IGNORE_LOCALHOST: Show queries from localhost
[2021-01-19 16:49:44.722 21969M]    BLOCKINGMODE: Null IPs for blocked domains
[2021-01-19 16:49:44.722 21969M]    ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2021-01-19 16:49:44.722 21969M]    DBIMPORT: Importing history from database
[2021-01-19 16:49:44.722 21969M]    PIDFILE: Using /run/pihole-FTL.pid
[2021-01-19 16:49:44.722 21969M]    PORTFILE: Using /run/pihole-FTL.port
[2021-01-19 16:49:44.723 21969M]    SOCKETFILE: Using /run/pihole/FTL.sock
[2021-01-19 16:49:44.723 21969M]    SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2021-01-19 16:49:44.723 21969M]    MACVENDORDB: Using /etc/pihole/macvendor.db
[2021-01-19 16:49:44.723 21969M]    GRAVITYDB: Using /etc/pihole/gravity.db
[2021-01-19 16:49:44.723 21969M]    PARSE_ARP_CACHE: Active
[2021-01-19 16:49:44.723 21969M]    CNAME_DEEP_INSPECT: Active
[2021-01-19 16:49:44.724 21969M]    DELAY_STARTUP: No delay requested.
[2021-01-19 16:49:44.724 21969M]    BLOCK_ESNI: Enabled, blocking _esni.{blocked domain}
[2021-01-19 16:49:44.724 21969M]    NICE: Set process niceness to -10 (default)
[2021-01-19 16:49:44.724 21969M]    MAXNETAGE: Removing IP addresses and host names from network table after 8 days
[2021-01-19 16:49:44.724 21969M]    NAMES_FROM_NETDB: Enabled, trying to get names from network database
[2021-01-19 16:49:44.725 21969M]    EDNS0_ECS: Overwrite client from ECS information
[2021-01-19 16:49:44.725 21969M]    REFRESH_HOSTNAMES: Only refreshing recently active clients with unknown hostnames
[2021-01-19 16:49:44.725 21969M] Finished config file parsing
[2021-01-19 16:49:44.726 21969M] Creating mutex
[2021-01-19 16:49:44.727 21969M] No database file found, creating new (empty) database
[2021-01-19 16:49:45.026 21969M] Database version is 1
[2021-01-19 16:49:45.026 21969M] Updating long-term database to version 2
[2021-01-19 16:49:45.125 21969M] Updating long-term database to version 3
[2021-01-19 16:49:45.151 21969M] Updating long-term database to version 4
[2021-01-19 16:49:45.165 21969M] Updating long-term database to version 5
[2021-01-19 16:49:45.189 21969M] Updating long-term database to version 6
[2021-01-19 16:49:45.217 21969M] Updating long-term database to version 7
[2021-01-19 16:49:45.277 21969M] Updating long-term database to version 8
[2021-01-19 16:49:45.309 21969M] Updating long-term database to version 9
[2021-01-19 16:49:45.357 21969M] Imported 0 alias-clients
[2021-01-19 16:49:45.357 21969M] Database successfully initialized
[2021-01-19 16:49:45.358 21969M] Imported 0 queries from the long-term database
[2021-01-19 16:49:45.359 21969M]  -> Total DNS queries: 0
[2021-01-19 16:49:45.359 21969M]  -> Cached DNS queries: 0
[2021-01-19 16:49:45.359 21969M]  -> Forwarded DNS queries: 0
[2021-01-19 16:49:45.359 21969M]  -> Blocked DNS queries: 0
[2021-01-19 16:49:45.359 21969M]  -> Unknown DNS queries: 0
[2021-01-19 16:49:45.359 21969M]  -> Unique domains: 0
[2021-01-19 16:49:45.360 21969M]  -> Unique clients: 0
[2021-01-19 16:49:45.360 21969M]  -> Known forward destinations: 0
[2021-01-19 16:49:45.360 21969M] Successfully accessed setupVars.conf
[2021-01-19 16:49:45.366 21971M] PID of FTL process: 21971
[2021-01-19 16:49:45.367 21971/T21972] Listening on port 4711 for incoming IPv4 telnet connections
[2021-01-19 16:49:45.368 21971/T21974] Listening on Unix socket
[2021-01-19 16:49:45.368 21971M] INFO: FTL is running as user pihole (UID 999)
[2021-01-19 16:49:45.369 21971/T21973] Listening on port 4711 for incoming IPv6 telnet connections
[2021-01-19 16:49:45.370 21971M] Reloading DNS cache
[2021-01-19 16:49:45.371 21971M] Blocking status is enabled
[2021-01-19 16:49:45.495 21971/T21975] Compiled 3 whitelist and 39 blacklist regex filters for 0 clients in 6.8 msec
[2021-01-19 16:50:28.153 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.153 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.154 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.154 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.154 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.154 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.155 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.155 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.156 21971M] New upstream server: fdaa:bbcc:ddee:2::5552:5552 (0/1024)
[2021-01-19 16:50:28.157 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.157 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.157 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.158 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.158 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.158 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.368 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.368 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.369 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.369 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.369 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.369 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.370 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.370 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.370 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.371 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.371 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.371 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.372 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.372 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.372 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.372 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.372 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.373 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.373 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.373 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.374 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.374 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.374 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.374 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.383 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.383 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.384 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.384 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.384 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.384 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.385 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.385 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.385 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.385 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.386 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.386 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.386 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.386 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:28.387 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.387 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:28.387 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:28.387 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:28.522 21971M] domain_in_list("228.2.168.192.in-addr.arpa", 0x7382b028, whitelist): Database is busy, assuming domain is NOT on list
[2021-01-19 16:50:29.272 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.272 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.272 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.272 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.272 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.273 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.274 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.274 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.274 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.275 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.275 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.275 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.281 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.281 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.282 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.282 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.282 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.282 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.284 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.284 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.284 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.285 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.285 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.285 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.783 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.783 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.784 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.784 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.784 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.784 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.786 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.786 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.786 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.786 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.787 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.787 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked
[2021-01-19 16:50:29.788 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.789 21971M] ERROR: Gravity database not available, assuming domain is not whitelisted
[2021-01-19 16:50:29.789 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.789 21971M] ERROR: Gravity database not available, assuming domain is not blacklisted
[2021-01-19 16:50:29.789 21971M] get_client_groupids("192.168.2.228") - SQL error step: database is locked
[2021-01-19 16:50:29.789 21971M] ERROR: Gravity database not available, assuming domain is not gravity blocked

DL6ER · January 19, 2021, 3:55pm

Yes, we haven't changed anything in this regard.

DL6ER · January 19, 2021, 4:03pm

Does this also happen without the external script (even when it worked before)?
I'm asking because we have not changed anything database-related in v5.5(.1) compared to v5.4:

Checking https://github.com/pi-hole/FTL/compare/release/v5.4...release/v5.5 we see that the only changes are:

Various commits caused by the dnsmasq update
Fix for Query Log filtering and memory optimizations by DL6ER · Pull Request #1032 · pi-hole/FTL · GitHub
Config option MAXDBDAYS fixes and tweaks by DL6ER · Pull Request #1033 · pi-hole/FTL · GitHub

edit I just verified with grep -c "Database is busy" /var/log/pihole-FTL.log that I don't see this message myself. I also tested the log files of two friends where I have VPN/SSH access to and there aren't any errors either (I updated them already as well).

ChurchOfNoise · January 19, 2021, 4:31pm

Running the grep -c "Database is busy" /var/log/pihole-FTL.log command, I get

63

as a result.
Running on dev btw.

jpgpi250 · January 19, 2021, 4:58pm

Sorry for the delay.
I checked my entire group management configuration, which is why I do the SQLITE3 inserts in the first place, everything appears to be OK, all entries appear to be OK.

Two questions:

If such an error (ERROR: Gravity database not available) is logged, does FTL retry, thus succeeding the second time?
is it possible this is caused by using sqlIte3 (version 3.27.2 2019-02-25 16:06:06), as opposed to pihole-FTL sqlite3 (version 3.34.0 2020-12-01 16:14:00)? I haven't gotten around to changing my scripts...

Max-Mustermann · January 19, 2021, 5:45pm

I got
pi@raspberrypi:/var/log $ grep -c "Database is busy" /var/log/pihole-FTL.log => 19

Max-Mustermann · January 19, 2021, 5:47pm

as per @DL6ER - he stated that it is normal behavior, as my best guess this happens when pihole is starting (DB) while requests coming from your NW devices .... correct me if I am wrong ....

But seems to be an error as you stated you checked log files on other devices and u haven't found any entries like these .....