Debug Token: https://tricorder.pi-hole.net/6frmbe4ntr
I was trying to triage an issue with perfoming long running SQL queries in pihole-ftl.db and switched between FTL branches new/all_clients_network_table and tweak/sqlite_debugging. As I was working over VPN I didn't noticed that FTL didn't run (DNS service not running, Lost connnection to API) when using sqlite_debugging. There was no error in pihole-ftl.log but I could see that the logging stopped right before it would print gravityDB_open(): Successfully opened gravity.db using new/all_clients_network_table.
I tried to switch between the branches a few times, rebooted the device but FTL didn't start properly using sqlite_debugging.
nanopi@nanopi:~$ systemctl status pihole-FTL.service
â—Ź pihole-FTL.service - LSB: pihole-FTL daemon
Loaded: loaded (/etc/init.d/pihole-FTL; generated)
Active: active (exited) since Sun 2020-03-22 19:23:04 CET; 34min ago
Docs: man:systemd-sysv-generator(8)
Tasks: 0 (limit: 1022)
Memory: 0B
CGroup: /system.slice/pihole-FTL.service
Mär 22 19:23:04 nanopi systemd[1]: Starting LSB: pihole-FTL daemon...
Mär 22 19:23:04 nanopi pihole-FTL[7629]: Not running
Mär 22 19:23:04 nanopi su[7657]: (to pihole) root on none
Mär 22 19:23:04 nanopi su[7657]: pam_unix(su:session): session opened for user pihole by (uid=0)
Mär 22 19:23:04 nanopi pihole-FTL[7629]: FTL started!
Mär 22 19:23:04 nanopi su[7657]: pam_unix(su:session): session closed for user pihole
Mär 22 19:23:04 nanopi systemd[1]: Started LSB: pihole-FTL daemon.
nanopi@nanopi:~$ pihole -v
Pi-hole version is v4.3.5-445-g22ce5c0 (Latest: v4.4)
AdminLTE version is v4.3.2-438-ga99bfea (Latest: v4.3.3)
FTL version is vDev-99bd5e7 (Latest: v4.3.1)
Using new/all_clients_network_table everything works fine.
DL6ER
March 23, 2020, 7:29am
3
Please try again, I extended the amount of debugging output and added fixed a small mistake where opening the database handle is tried again just before closing the database. This should have been harmless, but it was also useless, so I removed it.
Did not work....
2020-03-23 08:44:26.267 8271] Using log file /var/log/pihole-FTL.log
[2020-03-23 08:44:26.267 8271] ########## FTL started! ##########
[2020-03-23 08:44:26.267 8271] FTL branch: tweak/sqlite_debugging
[2020-03-23 08:44:26.267 8271] FTL version: vDev-2fbdf7b
[2020-03-23 08:44:26.267 8271] FTL commit: 2fbdf7b
[2020-03-23 08:44:26.267 8271] FTL date: 2020-03-23 08:33:28 +0100
[2020-03-23 08:44:26.267 8271] FTL user: pihole
[2020-03-23 08:44:26.267 8271] Compiled for aarch64 (compiled on CI) using aarch64-linux-gnu-gcc (Debian 6.3.0-18) 6.3.0 20170516
[2020-03-23 08:44:26.267 8271] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2020-03-23 08:44:26.267 8271] SOCKET_LISTENING: only local
[2020-03-23 08:44:26.267 8271] AAAA_QUERY_ANALYSIS: Show AAAA queries
[2020-03-23 08:44:26.268 8271] MAXDBDAYS: max age for stored queries is 365 days
[2020-03-23 08:44:26.268 8271] RESOLVE_IPV6: Resolve IPv6 addresses
[2020-03-23 08:44:26.268 8271] RESOLVE_IPV4: Resolve IPv4 addresses
[2020-03-23 08:44:26.268 8271] DBINTERVAL: saving to DB file every minute
[2020-03-23 08:44:26.268 8271] DBFILE: Using /etc/pihole/pihole-FTL.db
[2020-03-23 08:44:26.268 8271] MAXLOGAGE: Importing up to 24.0 hours of log data
[2020-03-23 08:44:26.268 8271] PRIVACYLEVEL: Set to 0
[2020-03-23 08:44:26.268 8271] IGNORE_LOCALHOST: Show queries from localhost
[2020-03-23 08:44:26.268 8271] BLOCKINGMODE: Null IPs for blocked domains
[2020-03-23 08:44:26.268 8271] ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2020-03-23 08:44:26.268 8271] DBIMPORT: Importing history from database
[2020-03-23 08:44:26.268 8271] PIDFILE: Using /var/run/pihole-FTL.pid
[2020-03-23 08:44:26.268 8271] PORTFILE: Using /var/run/pihole-FTL.port
[2020-03-23 08:44:26.268 8271] SOCKETFILE: Using /var/run/pihole/FTL.sock
[2020-03-23 08:44:26.268 8271] SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2020-03-23 08:44:26.268 8271] MACVENDORDB: Using /etc/pihole/macvendor.db
[2020-03-23 08:44:26.268 8271] GRAVITYDB: Using /etc/pihole/gravity.db
[2020-03-23 08:44:26.269 8271] PARSE_ARP_CACHE: Active
[2020-03-23 08:44:26.269 8271] REGEX_IGNORECASE: Disabled. Regex is case sensitive
[2020-03-23 08:44:26.269 8271] CNAME_DEEP_INSPECT: Active
[2020-03-23 08:44:26.269 8271] *****************************
[2020-03-23 08:44:26.269 8271] * Debugging enabled *
[2020-03-23 08:44:26.269 8271] * DEBUG_DATABASE YES *
[2020-03-23 08:44:26.269 8271] * DEBUG_NETWORKING NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_LOCKS NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_QUERIES NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_FLAGS NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_SHMEM NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_GC NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_ARP YES *
[2020-03-23 08:44:26.269 8271] * DEBUG_REGEX NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_API YES *
[2020-03-23 08:44:26.269 8271] * DEBUG_OVERTIME NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_EXTBLOCKED NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_CAPS NO *
[2020-03-23 08:44:26.269 8271] * DEBUG_DNSMASQ_LINES NO *
[2020-03-23 08:44:26.269 8271] *****************************
[2020-03-23 08:44:26.269 8271] Finished config file parsing
[2020-03-23 08:44:26.272 8271] Database version is 5
[2020-03-23 08:44:26.272 8271] Database successfully initialized
[2020-03-23 08:44:26.272 8271] DB_read_queries(): "SELECT * FROM queries WHERE timestamp >= 1584863066"
[2020-03-23 08:44:26.274 8271] New upstream server: 127.0.0.1 (0/128)
[2020-03-23 08:44:26.284 8271] Resizing "/FTL-strings" from 4096 to 8192
[2020-03-23 08:44:26.306 8271] Resizing "/FTL-strings" from 8192 to 12288
[2020-03-23 08:44:26.353 8271] Resizing "/FTL-strings" from 12288 to 16384
[2020-03-23 08:44:26.369 8271] Imported 3701 queries from the long-term database
[2020-03-23 08:44:26.370 8271] -> Total DNS queries: 3701
[2020-03-23 08:44:26.370 8271] -> Cached DNS queries: 1726
[2020-03-23 08:44:26.370 8271] -> Forwarded DNS queries: 1190
[2020-03-23 08:44:26.370 8271] -> Blocked DNS queries: 785
[2020-03-23 08:44:26.370 8271] -> Unknown DNS queries: 0
[2020-03-23 08:44:26.370 8271] -> Unique domains: 681
[2020-03-23 08:44:26.370 8271] -> Unique clients: 11
[2020-03-23 08:44:26.370 8271] -> Known forward destinations: 1
[2020-03-23 08:44:26.370 8271] Successfully accessed setupVars.conf
[2020-03-23 08:44:26.379 8273] PID of FTL process: 8273
[2020-03-23 08:44:26.379 8273] Listening on port 4711 for incoming IPv4 telnet connections
[2020-03-23 08:44:26.383 8273] Listening on port 4711 for incoming IPv6 telnet connections
[2020-03-23 08:44:26.383 8273] Listening on Unix socket
[2020-03-23 08:44:26.384 8273] Reloading DNS cache
[2020-03-23 08:44:26.385 8273] Blocking status is enabled
[2020-03-23 08:44:26.385 8273] *****************************
[2020-03-23 08:44:26.385 8273] * Debugging enabled *
[2020-03-23 08:44:26.385 8273] * DEBUG_DATABASE YES *
[2020-03-23 08:44:26.385 8273] * DEBUG_NETWORKING NO *
[2020-03-23 08:44:26.385 8273] * DEBUG_LOCKS NO *
[2020-03-23 08:44:26.385 8273] * DEBUG_QUERIES NO *
[2020-03-23 08:44:26.385 8273] * DEBUG_FLAGS NO *
[2020-03-23 08:44:26.385 8273] * DEBUG_SHMEM NO *
[2020-03-23 08:44:26.385 8273] * DEBUG_GC NO *
[2020-03-23 08:44:26.386 8273] * DEBUG_ARP YES *
[2020-03-23 08:44:26.386 8273] * DEBUG_REGEX NO *
[2020-03-23 08:44:26.386 8273] * DEBUG_API YES *
[2020-03-23 08:44:26.386 8273] * DEBUG_OVERTIME NO *
[2020-03-23 08:44:26.386 8273] * DEBUG_EXTBLOCKED NO *
[2020-03-23 08:44:26.386 8273] * DEBUG_CAPS NO *
[2020-03-23 08:44:26.386 8273] * DEBUG_DNSMASQ_LINES NO *
[2020-03-23 08:44:26.386 8273] *****************************
[2020-03-23 08:44:26.386 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.386 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.386 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.387 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.393 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.393 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.393 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.396 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.400 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.400 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.405 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.405 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.405 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.406 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.406 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.406 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.409 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.409 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.409 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.410 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.410 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.410 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.413 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.413 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.413 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.414 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.414 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.414 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.417 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.417 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.417 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.417 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.418 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.418 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.420 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.421 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.421 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.421 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.421 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.422 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.424 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.424 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.424 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.425 8273] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 08:44:26.425 8273] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 08:44:26.425 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:26.428 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:26.428 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:26.428 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:26.428 8273] gravityDB_open(): Setting busy timeout to zero
.....
[2020-03-23 08:44:29.815 8273] gravityDB_open(): Preparing audit query
[2020-03-23 08:44:29.818 8273] gravityDB_open(): Reloading client statements
[2020-03-23 08:44:29.818 8273] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 08:44:29.818 8273] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 08:44:55.904 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:56.049 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:56.059 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:56.062 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:56.085 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:56.106 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:44:58.065 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:45:00.118 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:45:01.143 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:45:05.218 8273] IPv4 telnet error: Too many open files (24)
[2020-03-23 08:45:05.245 8273] IPv4 telnet error: Too many open files (24)
......
DL6ER
March 23, 2020, 8:04am
5
Hmm,
[2020-03-23 08:44:55.904 8273] IPv4 telnet error: Too many open files (24)
is something we haven't seen before.
What is the output of
ulimit -a | grep open
?
Also, what is the output of
cat /proc/$(pidof pihole-FTL)/limits
while FTL is running?
Withnew/all_clients_network_table
nanopi@nanopi:~$ ulimit -a |grep open
open files (-n) 1024
nanopi@nanopi:~$ cat /proc/$(pidof pihole-FTL)/limits
Limit Soft Limit Hard Limit Units
Max cpu time unlimited unlimited seconds
Max file size unlimited unlimited bytes
Max data size unlimited unlimited bytes
Max stack size 8388608 unlimited bytes
Max core file size 0 unlimited bytes
Max resident set unlimited unlimited bytes
Max processes 3407 3407 processes
Max open files 1024 1048576 files
Max locked memory 67108864 67108864 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 3407 3407 signals
Max msgqueue size 819200 819200 bytes
Max nice priority 0 0
Max realtime priority 0 0
Max realtime timeout unlimited unlimited us
With tweak/sqlite_debugging
nanopi@nanopi:~$ ulimit -a |grep open
open files (-n) 1024
nanopi@nanopi:~$ cat /proc/$(pidof pihole-FTL)/limits
Limit Soft Limit Hard Limit Units
Max cpu time unlimited unlimited seconds
Max file size unlimited unlimited bytes
Max data size unlimited unlimited bytes
Max stack size 8388608 unlimited bytes
Max core file size 0 unlimited bytes
Max resident set unlimited unlimited bytes
Max processes 3407 3407 processes
Max open files 1024 1048576 files
Max locked memory 67108864 67108864 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 3407 3407 signals
Max msgqueue size 819200 819200 bytes
Max nice priority 0 0
Max realtime priority 0 0
Max realtime timeout unlimited unlimited us
DL6ER
March 23, 2020, 9:00am
7
Alright, I was able to track this down with spawning several mock-clients in my network. Too many clients caused to many concurrent gravity.db connections. This was a mistake, everything should go through one database connection. Fix pushed, please try again.
2 Likes
FTL started successfully.
pihole-FTL.log
[2020-03-23 10:12:08.175 17389] Using log file /var/log/pihole-FTL.log
[2020-03-23 10:12:08.175 17389] ########## FTL started! ##########
[2020-03-23 10:12:08.175 17389] FTL branch: tweak/sqlite_debugging
[2020-03-23 10:12:08.175 17389] FTL version: vDev-07c8de2
[2020-03-23 10:12:08.175 17389] FTL commit: 07c8de2
[2020-03-23 10:12:08.175 17389] FTL date: 2020-03-23 09:58:44 +0100
[2020-03-23 10:12:08.175 17389] FTL user: pihole
[2020-03-23 10:12:08.175 17389] Compiled for aarch64 (compiled on CI) using aarch64-linux-gnu-gcc (Debian 6.3.0-18) 6.3.0 20170516
[2020-03-23 10:12:08.175 17389] Starting config file parsing (/etc/pihole/pihole-FTL.conf)
[2020-03-23 10:12:08.175 17389] SOCKET_LISTENING: only local
[2020-03-23 10:12:08.175 17389] AAAA_QUERY_ANALYSIS: Show AAAA queries
[2020-03-23 10:12:08.175 17389] MAXDBDAYS: max age for stored queries is 365 days
[2020-03-23 10:12:08.175 17389] RESOLVE_IPV6: Resolve IPv6 addresses
[2020-03-23 10:12:08.175 17389] RESOLVE_IPV4: Resolve IPv4 addresses
[2020-03-23 10:12:08.175 17389] DBINTERVAL: saving to DB file every minute
[2020-03-23 10:12:08.175 17389] DBFILE: Using /etc/pihole/pihole-FTL.db
[2020-03-23 10:12:08.176 17389] MAXLOGAGE: Importing up to 24.0 hours of log data
[2020-03-23 10:12:08.176 17389] PRIVACYLEVEL: Set to 0
[2020-03-23 10:12:08.176 17389] IGNORE_LOCALHOST: Show queries from localhost
[2020-03-23 10:12:08.176 17389] BLOCKINGMODE: Null IPs for blocked domains
[2020-03-23 10:12:08.176 17389] ANALYZE_ONLY_A_AND_AAAA: Disabled. Analyzing all queries
[2020-03-23 10:12:08.176 17389] DBIMPORT: Importing history from database
[2020-03-23 10:12:08.176 17389] PIDFILE: Using /var/run/pihole-FTL.pid
[2020-03-23 10:12:08.176 17389] PORTFILE: Using /var/run/pihole-FTL.port
[2020-03-23 10:12:08.176 17389] SOCKETFILE: Using /var/run/pihole/FTL.sock
[2020-03-23 10:12:08.176 17389] SETUPVARSFILE: Using /etc/pihole/setupVars.conf
[2020-03-23 10:12:08.176 17389] MACVENDORDB: Using /etc/pihole/macvendor.db
[2020-03-23 10:12:08.176 17389] GRAVITYDB: Using /etc/pihole/gravity.db
[2020-03-23 10:12:08.176 17389] PARSE_ARP_CACHE: Active
[2020-03-23 10:12:08.176 17389] REGEX_IGNORECASE: Disabled. Regex is case sensitive
[2020-03-23 10:12:08.176 17389] CNAME_DEEP_INSPECT: Active
[2020-03-23 10:12:08.177 17389] *****************************
[2020-03-23 10:12:08.177 17389] * Debugging enabled *
[2020-03-23 10:12:08.177 17389] * DEBUG_DATABASE YES *
[2020-03-23 10:12:08.177 17389] * DEBUG_NETWORKING NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_LOCKS NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_QUERIES NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_FLAGS NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_SHMEM NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_GC NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_ARP YES *
[2020-03-23 10:12:08.177 17389] * DEBUG_REGEX NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_API YES *
[2020-03-23 10:12:08.177 17389] * DEBUG_OVERTIME NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_EXTBLOCKED NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_CAPS NO *
[2020-03-23 10:12:08.177 17389] * DEBUG_DNSMASQ_LINES NO *
[2020-03-23 10:12:08.177 17389] *****************************
[2020-03-23 10:12:08.177 17389] Finished config file parsing
[2020-03-23 10:12:08.180 17389] Database version is 5
[2020-03-23 10:12:08.180 17389] Database successfully initialized
[2020-03-23 10:12:08.180 17389] DB_read_queries(): "SELECT * FROM queries WHERE timestamp >= 1584868328"
[2020-03-23 10:12:08.181 17389] New upstream server: 127.0.0.1 (0/128)
[2020-03-23 10:12:08.191 17389] Resizing "/FTL-strings" from 4096 to 8192
[2020-03-23 10:12:08.206 17389] Resizing "/FTL-strings" from 8192 to 12288
[2020-03-23 10:12:08.234 17389] Resizing "/FTL-strings" from 12288 to 16384
[2020-03-23 10:12:08.247 17389] Resizing "/FTL-queries" from 262144 to 524288
[2020-03-23 10:12:08.253 17389] Imported 4406 queries from the long-term database
[2020-03-23 10:12:08.254 17389] -> Total DNS queries: 4406
[2020-03-23 10:12:08.254 17389] -> Cached DNS queries: 1941
[2020-03-23 10:12:08.254 17389] -> Forwarded DNS queries: 1487
[2020-03-23 10:12:08.254 17389] -> Blocked DNS queries: 943
[2020-03-23 10:12:08.254 17389] -> Unknown DNS queries: 35
[2020-03-23 10:12:08.254 17389] -> Unique domains: 712
[2020-03-23 10:12:08.254 17389] -> Unique clients: 9
[2020-03-23 10:12:08.254 17389] -> Known forward destinations: 1
[2020-03-23 10:12:08.254 17389] Successfully accessed setupVars.conf
[2020-03-23 10:12:08.262 17391] PID of FTL process: 17391
[2020-03-23 10:12:08.262 17391] Listening on port 4711 for incoming IPv4 telnet connections
[2020-03-23 10:12:08.263 17391] Listening on port 4711 for incoming IPv6 telnet connections
[2020-03-23 10:12:08.263 17391] Listening on Unix socket
[2020-03-23 10:12:08.265 17391] Reloading DNS cache
[2020-03-23 10:12:08.265 17391] Blocking status is enabled
[2020-03-23 10:12:08.265 17391] *****************************
[2020-03-23 10:12:08.265 17391] * Debugging enabled *
[2020-03-23 10:12:08.265 17391] * DEBUG_DATABASE YES *
[2020-03-23 10:12:08.265 17391] * DEBUG_NETWORKING NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_LOCKS NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_QUERIES NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_FLAGS NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_SHMEM NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_GC NO *
[2020-03-23 10:12:08.265 17391] * DEBUG_ARP YES *
[2020-03-23 10:12:08.265 17391] * DEBUG_REGEX NO *
[2020-03-23 10:12:08.266 17391] * DEBUG_API YES *
[2020-03-23 10:12:08.266 17391] * DEBUG_OVERTIME NO *
[2020-03-23 10:12:08.266 17391] * DEBUG_EXTBLOCKED NO *
[2020-03-23 10:12:08.266 17391] * DEBUG_CAPS NO *
[2020-03-23 10:12:08.266 17391] * DEBUG_DNSMASQ_LINES NO *
[2020-03-23 10:12:08.266 17391] *****************************
[2020-03-23 10:12:08.266 17391] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-03-23 10:12:08.268 17391] gravityDB_open(): Setting busy timeout to zero
[2020-03-23 10:12:08.268 17391] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-03-23 10:12:08.268 17391] gravityDB_open(): Preparing audit query
[2020-03-23 10:12:08.271 17391] gravityDB_open(): Reloading client statements
[2020-03-23 10:12:08.271 17391] gravityDB_open(): Setting busy timeout to 1000
[2020-03-23 10:12:08.271 17391] Initializing gravity statements for 10.0.30.254
[2020-03-23 10:12:08.271 17391] Querying gravity database for client 10.0.30.254
[2020-03-23 10:12:08.272 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.30.254
[2020-03-23 10:12:08.272 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.272 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.30.254
[2020-03-23 10:12:08.272 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.273 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.30.254
[2020-03-23 10:12:08.273 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.274 17391] Initializing gravity statements for 127.0.0.1
[2020-03-23 10:12:08.274 17391] Querying gravity database for client 127.0.0.1
[2020-03-23 10:12:08.274 17391] gravityDB_open(): Preparing vw_whitelist statement for client 127.0.0.1
[2020-03-23 10:12:08.274 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.275 17391] gravityDB_open(): Preparing vw_gravity statement for client 127.0.0.1
[2020-03-23 10:12:08.275 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.275 17391] gravityDB_open(): Preparing vw_blacklist statement for client 127.0.0.1
[2020-03-23 10:12:08.275 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.276 17391] Initializing gravity statements for 10.0.1.136
[2020-03-23 10:12:08.276 17391] Querying gravity database for client 10.0.1.136
[2020-03-23 10:12:08.286 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.136
[2020-03-23 10:12:08.286 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.286 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.136
[2020-03-23 10:12:08.287 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.287 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.136
[2020-03-23 10:12:08.287 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.288 17391] Initializing gravity statements for 10.0.1.2
[2020-03-23 10:12:08.288 17391] Querying gravity database for client 10.0.1.2
[2020-03-23 10:12:08.288 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.2
[2020-03-23 10:12:08.288 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.289 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.2
[2020-03-23 10:12:08.289 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.290 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.2
[2020-03-23 10:12:08.290 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.290 17391] Initializing gravity statements for 10.0.1.1
[2020-03-23 10:12:08.291 17391] Querying gravity database for client 10.0.1.1
[2020-03-23 10:12:08.291 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.1
[2020-03-23 10:12:08.291 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.292 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.1
[2020-03-23 10:12:08.292 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.292 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.1
[2020-03-23 10:12:08.292 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.293 17391] Initializing gravity statements for 10.0.1.215
[2020-03-23 10:12:08.293 17391] Querying gravity database for client 10.0.1.215
[2020-03-23 10:12:08.293 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.215
[2020-03-23 10:12:08.293 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.294 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.215
[2020-03-23 10:12:08.294 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.294 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.215
[2020-03-23 10:12:08.295 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.295 17391] Initializing gravity statements for 10.0.1.64
[2020-03-23 10:12:08.295 17391] Querying gravity database for client 10.0.1.64
[2020-03-23 10:12:08.295 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.64
[2020-03-23 10:12:08.295 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.296 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.64
[2020-03-23 10:12:08.296 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.296 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.64
[2020-03-23 10:12:08.297 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.297 17391] Initializing gravity statements for 10.0.1.182
[2020-03-23 10:12:08.297 17391] Querying gravity database for client 10.0.1.182
[2020-03-23 10:12:08.298 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.182
[2020-03-23 10:12:08.298 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.298 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.182
[2020-03-23 10:12:08.298 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.299 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.182
[2020-03-23 10:12:08.299 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.300 17391] Initializing gravity statements for 10.0.1.190
[2020-03-23 10:12:08.300 17391] Querying gravity database for client 10.0.1.190
[2020-03-23 10:12:08.300 17391] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.1.190
[2020-03-23 10:12:08.300 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.301 17391] gravityDB_open(): Preparing vw_gravity statement for client 10.0.1.190
[2020-03-23 10:12:08.301 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.302 17391] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.1.190
[2020-03-23 10:12:08.302 17391] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-03-23 10:12:08.302 17391] gravityDB_open(): Successfully opened gravity.db
[2020-03-23 10:12:08.302 17391] Querying count of distinct domains in gravity database table vw_gravity
[2020-03-23 10:12:08.302 17391] Querying count of distinct domains in gravity database table vw_regex_blacklist
[2020-03-23 10:12:08.306 17391] Querying count of distinct domains in gravity database table vw_regex_whitelist
[2020-03-23 10:12:08.308 17391] Querying gravity database for client 10.0.30.254
[2020-03-23 10:12:08.309 17391] Querying gravity database for client 10.0.30.254
[2020-03-23 10:12:08.310 17391] Querying gravity database for client 127.0.0.1
[2020-03-23 10:12:08.310 17391] Querying gravity database for client 127.0.0.1
[2020-03-23 10:12:08.311 17391] Querying gravity database for client 10.0.1.136
[2020-03-23 10:12:08.312 17391] Querying gravity database for client 10.0.1.136
[2020-03-23 10:12:08.312 17391] Querying gravity database for client 10.0.1.2
[2020-03-23 10:12:08.313 17391] Querying gravity database for client 10.0.1.2
[2020-03-23 10:12:08.314 17391] Querying gravity database for client 10.0.1.1
[2020-03-23 10:12:08.314 17391] Querying gravity database for client 10.0.1.1
[2020-03-23 10:12:08.315 17391] Querying gravity database for client 10.0.1.215
[2020-03-23 10:12:08.316 17391] Querying gravity database for client 10.0.1.215
[2020-03-23 10:12:08.316 17391] Querying gravity database for client 10.0.1.64
[2020-03-23 10:12:08.317 17391] Querying gravity database for client 10.0.1.64
[2020-03-23 10:12:08.318 17391] Querying gravity database for client 10.0.1.182
[2020-03-23 10:12:08.318 17391] Querying gravity database for client 10.0.1.182
[2020-03-23 10:12:08.319 17391] Querying gravity database for client 10.0.1.190
[2020-03-23 10:12:08.319 17391] Querying gravity database for client 10.0.1.190
[2020-03-23 10:12:08.320 17391] Compiled 1 whitelist and 23 blacklist regex filters in 17.5 msec
[2020-03-23 10:12:15.964 17391] domain_in_whitelist("mail.google.com"): 0
[2020-03-23 10:12:15.964 17391] domain_in_blacklist("mail.google.com"): 0
[2020-03-23 10:12:15.965 17391] domain_in_gravity("mail.google.com"): 0
[2020-03-23 10:12:15.973 17391] domain_in_whitelist("googlemail.l.google.com"): 0
[2020-03-23 10:12:15.973 17391] domain_in_blacklist("googlemail.l.google.com"): 0
[2020-03-23 10:12:15.974 17391] domain_in_gravity("googlemail.l.google.com"): 0
[2020-03-23 10:12:16.902 17391] domain_in_whitelist("calendar.google.com"): 0
[2020-03-23 10:12:16.902 17391] domain_in_blacklist("calendar.google.com"): 0
[2020-03-23 10:12:16.902 17391] domain_in_gravity("calendar.google.com"): 0
[2020-03-23 10:12:24.886 17391] domain_in_whitelist("ssl.gstatic.com"): 0
[2020-03-23 10:12:24.886 17391] domain_in_blacklist("ssl.gstatic.com"): 0
[2020-03-23 10:12:24.886 17391] domain_in_gravity("ssl.gstatic.com"): 0
[2020-03-23 10:12:30.757 17391] domain_in_whitelist("play.google.com"): 0
[2020-03-23 10:12:30.757 17391] domain_in_blacklist("play.google.com"): 0
[2020-03-23 10:12:30.758 17391] domain_in_gravity("play.google.com"): 0
[2020-03-23 10:12:44.064 17391] domain_in_whitelist("clients1.google.com"): 0
[2020-03-23 10:12:44.064 17391] domain_in_blacklist("clients1.google.com"): 0
[2020-03-23 10:12:44.064 17391] domain_in_gravity("clients1.google.com"): 0
[2020-03-23 10:12:44.066 17391] domain_in_whitelist("clients.l.google.com"): 0
[2020-03-23 10:12:44.066 17391] domain_in_blacklist("clients.l.google.com"): 0
[2020-03-23 10:12:44.066 17391] domain_in_gravity("clients.l.google.com"): 0
[2020-03-23 10:12:47.102 17391] domain_in_whitelist("clients4.google.com"): 0
[2020-03-23 10:12:47.102 17391] domain_in_blacklist("clients4.google.com"): 0
[2020-03-23 10:12:47.103 17391] domain_in_gravity("clients4.google.com"): 0
[2020-03-23 10:13:00.038 17391] dbquery: "BEGIN TRANSACTION"
[2020-03-23 10:13:00.040 17391] dbquery: "END TRANSACTION"
[2020-03-23 10:13:00.048 17391] dbquery: "INSERT OR REPLACE INTO ftl (id, value) VALUES ( 1, 1584954767 );"
[2020-03-23 10:13:00.054 17391] dbquery: "UPDATE counters SET value = value + 6 WHERE id = 0;"
[2020-03-23 10:13:00.061 17391] dbquery: "UPDATE counters SET value = value + 0 WHERE id = 1;"
[2020-03-23 10:13:00.061 17391] Notice: Queries stored in FTL_db: 6 (took 26.0 ms, last SQLite ID 2176786)
[2020-03-23 10:13:00.063 17391] dbquery: "BEGIN TRANSACTION"
[2020-03-23 10:13:00.074 17391] dbquery: "UPDATE network SET lastQuery = MAX(lastQuery, 1584954633) WHERE id = 5;"
[2020-03-23 10:13:00.074 17391] dbquery: "UPDATE network SET numQueries = numQueries + 1221 WHERE id = 5;"
[2020-03-23 10:13:00.075 17391] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip) VALUES(5,'10.0.1.190');"
[2020-03-23 10:13:00.075 17391] dbquery: "UPDATE network SET lastQuery = MAX(lastQuery, 1584954408) WHERE id = 4;"
[2020-03-23 10:13:00.075 17391] dbquery: "UPDATE network SET numQueries = numQueries + 57 WHERE id = 4;"
[2020-03-23 10:13:00.075 17391] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip) VALUES(4,'10.0.1.1');"
[2020-03-23 10:13:00.076 17391] dbquery: "UPDATE network SET lastQuery = MAX(lastQuery, 1584954767) WHERE id = 1;"
[2020-03-23 10:13:00.076 17391] dbquery: "UPDATE network SET numQueries = numQueries + 2606 WHERE id = 1;"
[2020-03-23 10:13:00.076 17391] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip) VALUES(1,'10.0.1.136');"
[2020-03-23 10:13:00.076 17391] dbquery: "COMMIT"
[2020-03-23 10:13:00.082 17391] ARP table processing (3 entries) took 18.9 ms
[2020-03-23 10:13:00.323 17391] domain_in_whitelist("254.30.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.323 17391] domain_in_blacklist("254.30.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.324 17391] domain_in_gravity("254.30.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.326 17391] domain_in_whitelist("136.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.326 17391] domain_in_blacklist("136.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.326 17391] domain_in_gravity("136.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.327 17391] domain_in_whitelist("2.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.328 17391] domain_in_blacklist("2.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.328 17391] domain_in_gravity("2.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.329 17391] domain_in_whitelist("1.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.329 17391] domain_in_blacklist("1.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.329 17391] domain_in_gravity("1.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.346 17391] domain_in_whitelist("215.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.346 17391] domain_in_blacklist("215.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.346 17391] domain_in_gravity("215.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.348 17391] domain_in_whitelist("64.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.348 17391] domain_in_blacklist("64.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.348 17391] domain_in_gravity("64.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.349 17391] domain_in_whitelist("182.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.349 17391] domain_in_blacklist("182.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.349 17391] domain_in_gravity("182.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.350 17391] domain_in_whitelist("190.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.350 17391] domain_in_blacklist("190.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.350 17391] domain_in_gravity("190.1.0.10.in-addr.arpa"): 0
[2020-03-23 10:13:00.351 17391] 9 / 9 client host names resolved
[2020-03-23 10:13:00.351 17391] 1 / 1 upstream server host names resolved
1 Like