Yes, I agreed. I got the same results whether starting via systemd or via sudo -u pihole /usr/bin/pihole-FTL -f
Very puzzling.
Okay, so it seems we are not getting to the bottom of it by just poking around. Hence, I added a temporary sigtest mode to FTL from the Pi-hole v6.0 beta. No worries, you will not have to switch to the beta, just grab the suitable binary from here: index - powered by h5ai v0.30.0 (https://larsjung.de/h5ai/)
Then run it as follows (assuming you renamed it to pihole-FTL):
chmod +x ./pihole-FTL
./pihole-FTL sigtest
it will print the PID and then wait for 30 seconds for any signals[1] to arrive.
When hitting Ctrl + C, you should be seeing
Received signal 2: "Interrupt"
When running kill <PID> you should see:
Received signal 15: "Terminated"
It is expected that the binary does actually not terminate here - it quits automatically after said 30 seconds. The particular strings may differ between the Linux flavors.
Remember: neither
SIGKILLnorSIGSTOPcan be caught (cfm.man 7 signal). ↩︎
1 Like
Thank you. Here is what executing the following in order:
# kill -SIGTERM $(pidof pihole-FTL-amd64)
# kill $(pidof pihole-FTL-amd64)
# kill -SIGKILL $(pidof pihole-FTL-amd64)
% ./pihole-FTL-amd64 sigtest
PID: 232
Waiting (30sec)...
Received signal 15: "Terminated"
Received signal 15: "Terminated"
[1] 232 killed ./pihole-FTL-amd64 sigtest
When I hit ctrl+c in the term, I get the expected:
% ./pihole-FTL-amd64 sigtest
PID: 320
Waiting (30sec)...
^CReceived signal 2: "Interrupt"
Any other tests?
You could use pihole-FTL sigtest instead of no-daemon:
in the systemd unit, start it, then issue service stop and finally check the systemd logs for what they printed.
Here is the output after starting, then stopping:
× pihole-FTL.service - Pi-hole FTLDNS engine
Loaded: loaded (/usr/lib/systemd/system/pihole-FTL.service; enabled; preset: disabled)
Drop-In: /run/systemd/system/service.d
└─zzz-lxc-service.conf
Active: failed (Result: timeout) since Fri 2024-07-19 08:09:57 EDT; 3s ago
Duration: 5.976s
Invocation: c23ae81ddee04b2bb64345e5c0c593c4
Process: 1243 ExecStartPre=/usr/bin/chown -R pihole:pihole /etc/pihole (code=exited, status=0/SUCCESS)
Process: 1245 ExecStartPre=/usr/bin/chown root:root /etc/pihole/logrotate (code=exited, status=0/SUCCESS)
Process: 1247 ExecStartPre=/usr/bin/sh -c /usr/bin/rm -f /dev/shm/FTL-* (code=exited, status=0/SUCCESS)
Process: 1249 ExecStart=/usr/bin/pihole-FTL-amd64 sigtest (code=killed, signal=KILL)
Main PID: 1249 (code=killed, signal=KILL)
Jul 19 08:09:46 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 19 08:09:46 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 19 08:09:46 test pihole-FTL-amd64[1249]: PID: 1249
Jul 19 08:09:52 test systemd[1]: Stopping Pi-hole FTLDNS engine...
Jul 19 08:09:57 test systemd[1]: pihole-FTL.service: State 'stop-sigterm' timed out. Killing.
Jul 19 08:09:57 test systemd[1]: pihole-FTL.service: Killing process 1249 (pihole-FTL-amd6) with signal SIGKILL.
Jul 19 08:09:57 test systemd[1]: pihole-FTL.service: Main process exited, code=killed, status=9/KILL
Jul 19 08:09:57 test systemd[1]: pihole-FTL.service: Failed with result 'timeout'.
Jul 19 08:09:57 test systemd[1]: Stopped Pi-hole FTLDNS engine.
Here is service file for reference:
[Unit]
Description=Pi-hole FTLDNS engine
After=network.target
[Service]
User=pihole
Group=pihole
PIDFile=/run/pihole-ftl/pihole-FTL.pid
ExecStartPre=/usr/bin/chown -R pihole:pihole /etc/pihole
ExecStartPre=-/usr/bin/chown root:root /etc/pihole/logrotate
ExecStartPre=-/usr/bin/sh -c '/usr/bin/rm -f /dev/shm/FTL-*'
#ExecStart=/usr/bin/pihole-FTL no-daemon
ExecStart=/usr/bin/pihole-FTL-amd64 sigtest
Restart=on-failure
TimeoutStopSec=5s
PermissionsStartOnly=true
AmbientCapabilities=CAP_NET_BIND_SERVICE CAP_NET_RAW CAP_NET_ADMIN CAP_SYS_NICE CAP_IPC_LOCK CAP_CHOWN
[Install]
WantedBy=multi-user.target
As we assumed: the SIGTERM didn't make it through to FTL and systemd killed it hard (08:09:57) five seconds after the signal should have been there (08:09:52). There's no chance for FTL to shutdown properly under these circumstances.
It works fine for me omy Ubuntu test setup, so I'm pretty sure some Arch Linux specific thing is happening here. Unfortunately, I cannot really help you debugging this as I have never used Arch myself.
Thanks for confirming. I don't see anything in the PKGBUILD for systemd that would explain a different behavior. In fact, introducing such modifications would be against a core philosophy of the Distro.
Currently, Arch is shipping systemd-256.2. Is this the same version your Ubuntu test setup uses?
$ systemd --version
systemd 249 (249.11-0ubuntu3.12)
+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified
Please update and try again, it seems there is an issue with systems where it may not log all printed lines without flushing if a process is forcefully terminated.
What I see is:
Jul 21 21:01:21 ryzen systemd[1]: Started Pi-hole FTL.
Jul 21 21:01:21 ryzen pihole-FTL[3138141]: PID: 3138141
Jul 21 21:01:21 ryzen pihole-FTL[3138141]: Waiting (30sec)...
Jul 21 21:01:27 ryzen pihole-FTL[3138141]: Received signal 18: "Continued"
Jul 21 21:01:27 ryzen pihole-FTL[3138141]: Received signal 15: "Terminated"
Jul 21 21:01:27 ryzen systemd[1]: Stopping Pi-hole FTL...
Jul 21 21:01:27 ryzen systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 21 21:01:27 ryzen systemd[1]: Stopped Pi-hole FTL.
(journalctl -u pihole-FTL.service)
I grabbed the updated binary. Here is the output after starting, then stopping:
% journalctl -u pihole-FTL.service
...
Jul 21 15:58:10 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 21 15:58:10 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 21 15:58:10 test pihole-FTL-amd64[128]: PID: 128
Jul 21 15:58:40 test pihole-FTL-amd64[128]: Waiting (30sec)...
Jul 21 15:58:40 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 21 16:02:51 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 21 16:02:51 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 21 16:02:51 test pihole-FTL-amd64[640]: PID: 640
Jul 21 16:02:56 test pihole-FTL-amd64[640]: Waiting (30sec)...
Jul 21 16:02:56 test pihole-FTL-amd64[640]: Received signal 18: "Continued"
Jul 21 16:02:56 test pihole-FTL-amd64[640]: Received signal 15: "Terminated"
Jul 21 16:02:56 test systemd[1]: Stopping Pi-hole FTLDNS engine...
Jul 21 16:02:56 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 21 16:02:56 test systemd[1]: Stopped Pi-hole FTLDNS engine.
Weird. This shows we were on the wrong track: systemd is behaving as it should and the signal is reaching FTL in sigtest mode.
This somewhat leases us grasping at nothing again. So I went ahead and added further debug printing, please update your pihole-FTL once again and set debug.extra = true:
sudo pihole-FTL --config debug.extra true
We expect to see something like:
2024-07-22 10:05:31.099 CEST [3353289M] DEBUG_ANY: Received SIGTERM
2024-07-22 10:05:31.099 CEST [3353289M] INFO: Asked to terminate by "/sbin/init" (PID 1, user root UID 0)
2024-07-22 10:05:31.099 CEST [3353289M] DEBUG_ANY: Sending SIGUSR6 to dnsmasq to stop DNS service
2024-07-22 10:05:31.099 CEST [3353289M] DEBUG_ANY: dnsmasq received signal 40
2024-07-22 10:05:31.099 CEST [3353289M] INFO: Shutting down... // exit code 0 // jmpret 0
2024-07-22 10:05:31.440 CEST [3353289M] INFO: Finished final database update
2024-07-22 10:05:31.440 CEST [3353289M] INFO: Waiting for threads to join
in /var/log/pihole/FTL.log on a stop/restart attempt. Let's see how much of this we get on your system.
New bin downloaded. Ran with the following in the systemd service:
/usr/bin/pihole-FTL-amd64 --config debug.extra true
Here is what journalctl captured when I stopped it:
Jul 22 16:15:05 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 22 16:15:05 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 22 16:15:05 test pihole-FTL-amd64[140]: PID: 140
Jul 22 16:15:35 test pihole-FTL-amd64[140]: Waiting (30sec)...
Jul 22 16:15:35 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 22 16:17:10 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 22 16:17:q0 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 22 16:17:10 test pihole-FTL-amd64[743]: true
Jul 22 16:17:11 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Not seeing any of the debug stuff. The sha1 sum checked out.
% sha1sum -c pihole-FTL-amd64.sha1
pihole-FTL-amd64: OK
Sorry, forgot to mention you should undo the systems unit modifications (sigtest) and go back to normal operation mode
I did not call it with sigtest. Is this incorrect:
[Unit]
Description=Pi-hole FTLDNS engine
After=network.target
[Service]
User=pihole
Group=pihole
PIDFile=/run/pihole-ftl/pihole-FTL.pid
ExecStartPre=/usr/bin/chown -R pihole:pihole /etc/pihole
ExecStartPre=-/usr/bin/chown root:root /etc/pihole/logrotate
ExecStartPre=-/usr/bin/sh -c '/usr/bin/rm -f /dev/shm/FTL-*'
#ExecStart=/usr/bin/pihole-FTL no-daemon
ExecStart=/usr/bin/pihole-FTL-amd64 --config debug.extra true
Restart=on-failure
TimeoutStopSec=5s
PermissionsStartOnly=true
AmbientCapabilities=CAP_NET_BIND_SERVICE CAP_NET_RAW CAP_NET_ADMIN CAP_SYS_NICE CAP_IPC_LOCK CAP_CHOWN
[Install]
WantedBy=multi-user.target
Ah, call it with no-daemon like normal, but run pihole-FTL-amd64 --config debug.extra true before you start the service. (You can also set the flag in /etc/pihole/pihole.toml (going off memory for the filename, but it should be the only toml file 
the --config CLI option doesn't actually start FTL, it just parses/sets the config values.
If you're feeling slightly fancier, you could also set it with an environment variable of FTLCONF_debug_extra=true, which we take advantage of in the v6 docker image
OK... here is the modified service:
[Unit]
Description=Pi-hole FTLDNS engine
After=network.target
[Service]
Environment="FTLCONF_debug_extra=true"
User=pihole
Group=pihole
PIDFile=/run/pihole-ftl/pihole-FTL.pid
ExecStartPre=/usr/bin/chown -R pihole:pihole /etc/pihole
ExecStartPre=-/usr/bin/chown root:root /etc/pihole/logrotate
ExecStartPre=-/usr/bin/sh -c '/usr/bin/rm -f /dev/shm/FTL-*'
ExecStart=/usr/bin/pihole-FTL-amd64 no-daemon
Restart=on-failure
TimeoutStopSec=5s
PermissionsStartOnly=true
AmbientCapabilities=CAP_NET_BIND_SERVICE CAP_NET_RAW CAP_NET_ADMIN CAP_SYS_NICE CAP_IPC_LOCK CAP_CHOWN
[Install]
WantedBy=multi-user.target
And the corresponding journalctl:
Jul 23 09:51:52 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 23 09:51:52 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 23 09:51:52 test pihole-FTL-amd64[117]: true
Jul 23 09:51:52 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 23 09:54:46 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 23 09:54:47 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 23 09:54:47 test pihole-FTL-amd64[210]: true
Jul 23 09:54:47 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 23 09:54:53 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 23 09:54:53 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 23 09:54:53 test [325]: Opening of FTL's log file failed, using syslog instead!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: ERROR: Opening of FTL log (/var/log/pihole/FTL.log) failed!
Jul 23 09:54:53 test [325]: ########## FTL started on test! ##########
Jul 23 09:54:53 test [325]: FTL branch: new/sigtest
Jul 23 09:54:53 test [325]: FTL version: vDev-c3a998f
Jul 23 09:54:53 test [325]: FTL commit: c3a998f3
Jul 23 09:54:53 test [325]: FTL date: 2024-07-22 10:01:09 +0200
Jul 23 09:54:53 test [325]: FTL user: pihole
Jul 23 09:54:53 test [325]: Compiled for linux/amd64 (compiled on CI) using cc (Alpine 13.2.1_git20240309) 13.2.1 20240309
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.319 EDT [325M] INFO: ########## FTL started on test! ##########
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.319 EDT [325M] INFO: FTL branch: new/sigtest
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.320 EDT [325M] INFO: FTL version: vDev-c3a998f
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.320 EDT [325M] INFO: FTL commit: c3a998f3
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.320 EDT [325M] INFO: FTL date: 2024-07-22 10:01:09 +0200
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.320 EDT [325M] INFO: FTL user: pihole
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.320 EDT [325M] INFO: Compiled for linux/amd64 (compiled on CI) u>
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: ************************
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * DEBUG SETTINGS *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * DATABASE: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * NETWORKING: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * LOCKS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * QUERIES: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * FLAGS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * SHMEM: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * GC: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * ARP: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * REGEX: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * API: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * TLS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * OVERTIME: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * STATUS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * CAPS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * DNSSEC: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * VECTORS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * RESOLVER: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * EDNS0: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * CLIENTS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * ALIASCLIENTS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * EVENTS: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * HELPER: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * CONFIG: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * INOTIFY: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * WEBSERVER: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * EXTRA: YES *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * RESERVED: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: * NTP: NO *
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] DEBUG_ANY: ************************
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.321 EDT [325M] INFO: 1 FTLCONF environment variable found (1 use>
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: [✓] FTLCONF_debug_extra is used
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: Wrote config file:
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: - 148 total entries
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: - 132 entries are default
Jul 23 09:54:53 test pihole-FTL-amd64[325]: dnsmasq: cannot open log /var/log/pihole/pihole.log: No such file or directory
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: - 16 entries are modified
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.322 EDT [325M] INFO: - 1 entry is forced through environment
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.323 EDT [325M] INFO: Config file written to /etc/pihole/pihole.t>
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.323 EDT [325M] INFO: Parsed config file /etc/pihole/pihole.toml >
Jul 23 09:54:53 test pihole-FTL-amd64[325]: 2024-07-23 09:54:53.324 EDT [325M] INFO: PID of FTL process: 325
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Initializing random number generator...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Generating EC key...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Generating new CA with serial number 572190934156203...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Generating new server certificate with serial number 880921072071620...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Storing CA certificate in /etc/pihole/tls_ca.crt ...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Storing server certificate in /etc/pihole/tls.crt ...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: Storing server key + certificate in /etc/pihole/tls.pem ...
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:54:53 test pihole-FTL-amd64[325]: !!! WARNING: Writing to web log file failed!
Jul 23 09:55:15 test systemd[1]: Stopping Pi-hole FTLDNS engine...
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: State 'stop-sigterm' timed out. Killing.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 325 (pihole-FTL-amd6) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 328 (NTP (IPv4)) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 329 (NTP (IPv6)) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 330 (ntp-client) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 331 (database) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 333 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 334 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 336 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 337 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 338 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 339 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 340 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 341 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 342 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 343 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 344 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 345 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 347 (civetweb-worker) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 349 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 350 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 351 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 352 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 355 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Killing process 358 (n/a) with signal SIGKILL.
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Main process exited, code=killed, status=9/KILL
Jul 23 09:55:20 test systemd[1]: pihole-FTL.service: Failed with result 'timeout'.
Jul 23 09:55:20 test systemd[1]: Stopped Pi-hole FTLDNS engine.
Too bad - the extra debug logging did not print anything so there still seems to be something wrong with the signal handling here ... however, I did notice
and
While I don't think that this would actually influence the results, you should check your system and the log file paths. Typically, the Pi-hole installer creates them for you - obviously not on Arch, though.
Yes, the Arch package uses an alternative path. I created the one it expects. Results:
Jul 23 17:09:38 test systemd[1]: Starting Pi-hole FTLDNS engine...
Jul 23 17:09:38 test systemd[1]: Started Pi-hole FTLDNS engine.
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: ########## FTL started on test! ##########
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: FTL branch: new/sigtest
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: FTL version: vDev-c3a998f
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: FTL commit: c3a998f3
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: FTL date: 2024-07-22 10:01:09 +0200
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: FTL user: pihole
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.789 EDT [399M] INFO: Compiled for linux/amd64 (compiled on CI) using cc (Alpine 13.2.1_git20240309) 13.2.1 20240309
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.790 EDT [399M] DEBUG_ANY: ************************
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.790 EDT [399M] DEBUG_ANY: * DEBUG SETTINGS *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.790 EDT [399M] DEBUG_ANY: * DATABASE: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.790 EDT [399M] DEBUG_ANY: * NETWORKING: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * LOCKS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * QUERIES: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * FLAGS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * SHMEM: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * GC: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * ARP: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * REGEX: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * API: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * TLS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * OVERTIME: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * STATUS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * CAPS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * DNSSEC: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * VECTORS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * RESOLVER: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * EDNS0: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * CLIENTS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * ALIASCLIENTS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * EVENTS: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * HELPER: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * CONFIG: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * INOTIFY: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * WEBSERVER: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * EXTRA: YES *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * RESERVED: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: * NTP: NO *
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] DEBUG_ANY: ************************
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] INFO: 1 FTLCONF environment variable found (1 used, 0 invalid, 0 ignored)
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.791 EDT [399M] INFO: [✓] FTLCONF_debug_extra is used
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.792 EDT [399M] INFO: Wrote config file:
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.792 EDT [399M] INFO: - 148 total entries
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.792 EDT [399M] INFO: - 132 entries are default
Jul 23 17:09:38 test pihole-FTL-amd64[399]: 2024-07-23 17:09:38.792 EDT [399M] INFO: - 16 entries are modified
Jul 23 17:09:46 test systemd[1]: Stopping Pi-hole FTLDNS engine...
Jul 23 17:09:46 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 23 17:09:46 test systemd[1]: Stopped Pi-hole FTLDNS engine.
Well, did it work this time?
Last time:
Now:
Please check the FTL.log file.
I agree that none of other lines are present after creating /var/log/pihole/pihole.log which I cannot explain.
Here is what I get on a fresh test:
% journalctl -u pihole-FTL.service
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * QUERIES: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * FLAGS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * SHMEM: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * GC: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * ARP: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * REGEX: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * API: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * TLS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * OVERTIME: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * STATUS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * CAPS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * DNSSEC: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * VECTORS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * RESOLVER: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * EDNS0: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * CLIENTS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * ALIASCLIENTS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * EVENTS: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * HELPER: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * CONFIG: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * INOTIFY: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * WEBSERVER: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * EXTRA: YES *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * RESERVED: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: * NTP: NO *
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] DEBUG_ANY: ************************
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] INFO: 1 FTLCONF environment variable found (1 used, 0 invalid, 0 ignored)
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.312 EDT [292M] INFO: [✓] FTLCONF_debug_extra is used
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.313 EDT [292M] INFO: Wrote config file:
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.313 EDT [292M] INFO: - 148 total entries
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.313 EDT [292M] INFO: - 132 entries are default
Jul 24 15:11:01 test pihole-FTL-amd64[292]: 2024-07-24 15:11:01.313 EDT [292M] INFO: - 16 entries are modified
Jul 24 15:11:15 test systemd[1]: Stopping Pi-hole FTLDNS engine...
Jul 24 15:11:17 test systemd[1]: pihole-FTL.service: Deactivated successfully.
Jul 24 15:11:17 test systemd[1]: Stopped Pi-hole FTLDNS engine.
And the corresponding /var/log/pihole/pihole.log
Jul 24 15:11:01 dnsmasq[292]: started, version pi-hole-v2.90+2 cachesize 10000
Jul 24 15:11:01 dnsmasq[292]: compile time options: IPv6 GNU-getopt no-DBus no-UBus no-i18n IDN2 DHCP DHCPv6 Lua TFTP no-conntrack ipset no-nftset auth cryptohash DNSSEC loop-detect inotify dumpfile
Jul 24 15:11:01 dnsmasq[292]: DNSSEC validation enabled
Jul 24 15:11:01 dnsmasq[292]: configured with trust anchor for <root> keytag 20326
Jul 24 15:11:01 dnsmasq[292]: using nameserver 1.1.1.1#53
Jul 24 15:11:01 dnsmasq[292]: using nameserver 1.0.0.1#53
Jul 24 15:11:01 dnsmasq[292]: using nameserver 10.9.8.1#53 for domain 9.10.in-addr.arpa (no DNSSEC)
Jul 24 15:11:01 dnsmasq[292]: using nameserver 10.9.8.1#53 for domain lan (no DNSSEC)
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for onion
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for bind
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for invalid
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for localhost
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for test
Jul 24 15:11:01 dnsmasq[292]: using only locally-known addresses for lan
Jul 24 15:11:01 dnsmasq[292]: read /etc/hosts - 3 names
Jul 24 15:11:01 dnsmasq[292]: read /etc/pihole/hosts/custom.list - 0 names
Jul 24 15:11:15 dnsmasq[292]: exiting on receipt of SIGTERM
Well, that's exactly what we wanted to see. FTL.log should now contain lines showing you that the expected final database storing was done on exit.
I'll have another look in the code how the log file issue could possibly cause this to happen.
How/where is it configured?