FTL Development crashes

[DL6ER]

I'm not sure if related, but I am experiencing crashes too on the Dev branch. Is this behind the release/v4.2 branch?

A recent update seems to be causing FTL to crash all the time. I had initially discovered it to be because I tried to convert my wildcards to NULL block with address=/test.com/#, but reverted this and removed any other conflicts out of the equation, fresh install and still falling over after a short time (less than a minute).

Can't keep the service up unless checking out the master branch. Haven't tried the one mentioned above.

Edit: Also - When unable to access the github repo for FTL, it claims there is an update available and tries to proceed with an install. After editing resolv.conf and restoring internet access, it reports that it is up-to-date. Only seems to be an issue for FTL.

Edit edit: Restarting the service or running sudo killall -SIGHUP pihole-FTL kills latest dev.

_Originally posted by @mmotti in https://github.com/pi-hole/FTL/issues/460#issuecomment-453596109_

[DL6ER]

@mmotti I isolated your issue to a separate thread. I do not see such crashes, but this surely needs to be resolved. development is more recent than release/v4.2 and contains all changes which are therein.

Questions:

1. Does release/v4.2 also crash for you?
2. (Independent from Q1): Do you receive a backtrace in the log? If so, please post it here.
3. Are you willing to help debugging pihole-FTL in case the backtrace isn't available or inconclusive? It seems that the crash is reproducible for you, so this would ease debugging a lot. We made debugging of FTL rather easy. Instructions are described here: https://docs.pi-hole.net/ftldns/debugging/

[mmotti]

Thanks @DL6ER. I'll do what I can.

Will report back soon when I have had a chance to switch branch back.

Any particular log to be looking through?

[mmotti]

OK, so just confirming.

Checked out the dev branch again, DNS resolution working.

Wait x amount of time or restart pihole-FTL service then wait x amount of time and DNS resolution fails and service seems to enter a failed state.

Here's a snapshot of /var/log/syslog which gives some indication of Pi-hole failure.

Jan 12 10:04:33 raspberrypi systemd[1]: Stopping LSB: pihole-FTL daemon...
Jan 12 10:04:38 raspberrypi pihole-FTL[19196]: .....
Jan 12 10:04:38 raspberrypi pihole-FTL[19196]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Jan 12 10:04:38 raspberrypi systemd[1]: pihole-FTL.service: Control process exited, code=exited status=1
Jan 12 10:04:38 raspberrypi systemd[1]: Stopped LSB: pihole-FTL daemon.
Jan 12 10:04:38 raspberrypi systemd[1]: pihole-FTL.service: Unit entered failed state.
Jan 12 10:04:38 raspberrypi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Jan 12 10:04:39 raspberrypi kernel: [60328.760772] Under-voltage detected! (0x00050005)
Jan 12 10:04:44 raspberrypi systemd[1]: Stopping User Manager for UID 999...
Jan 12 10:04:44 raspberrypi systemd[16024]: Stopped target Default.
Jan 12 10:04:44 raspberrypi systemd[16024]: Stopped target Basic System.
Jan 12 10:04:44 raspberrypi systemd[16024]: Stopped target Sockets.
Jan 12 10:04:44 raspberrypi systemd[16024]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:04:44 raspberrypi systemd[16024]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:04:44 raspberrypi systemd[16024]: Closed GnuPG cryptographic agent and passphrase cache.
Jan 12 10:04:44 raspberrypi systemd[16024]: Closed GnuPG cryptographic agent (access for web browsers).
Jan 12 10:04:44 raspberrypi systemd[16024]: Reached target Shutdown.
Jan 12 10:04:44 raspberrypi systemd[16024]: Starting Exit the Session...
Jan 12 10:04:44 raspberrypi systemd[16024]: Stopped target Timers.
Jan 12 10:04:44 raspberrypi systemd[16024]: Stopped target Paths.
Jan 12 10:04:44 raspberrypi systemd[16024]: Received SIGRTMIN+24 from PID 19282 (kill).
Jan 12 10:04:44 raspberrypi systemd[1]: Stopped User Manager for UID 999.
Jan 12 10:04:44 raspberrypi systemd[1]: Removed slice User Slice of pihole.
Jan 12 10:04:45 raspberrypi kernel: [60335.000782] Voltage normalised (0x00000000)
Jan 12 10:05:01 raspberrypi cron[357]: (*system*pihole) RELOAD (/etc/cron.d/pihole)
Jan 12 10:05:01 raspberrypi CRON[19292]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan 12 10:06:00 raspberrypi systemd[1]: Stopping Lighttpd Daemon...
Jan 12 10:06:00 raspberrypi systemd[1]: Stopped Lighttpd Daemon.
Jan 12 10:06:00 raspberrypi systemd[1]: Starting Lighttpd Daemon...
Jan 12 10:06:01 raspberrypi systemd[1]: Started Lighttpd Daemon.
Jan 12 10:06:01 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:01 raspberrypi systemd[1]: apt-daily.timer: Adding 52min 36.307281s random time.
Jan 12 10:06:01 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:01 raspberrypi systemd[1]: apt-daily.timer: Adding 5h 30min 7.827421s random time.
Jan 12 10:06:01 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:02 raspberrypi systemd[1]: apt-daily.timer: Adding 3h 59min 54.661066s random time.
Jan 12 10:06:02 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:02 raspberrypi systemd[1]: apt-daily.timer: Adding 3h 37min 6.307812s random time.
Jan 12 10:06:02 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:02 raspberrypi systemd[1]: apt-daily.timer: Adding 6h 18min 29.217222s random time.
Jan 12 10:06:02 raspberrypi systemd[1]: Reloading.
Jan 12 10:06:02 raspberrypi systemd[1]: apt-daily.timer: Adding 8h 19min 29.237611s random time.
Jan 12 10:06:03 raspberrypi systemd[1]: Starting LSB: pihole-FTL daemon...
Jan 12 10:06:03 raspberrypi pihole-FTL[19438]: Not running
Jan 12 10:06:13 raspberrypi systemd[1]: Created slice User Slice of pihole.
Jan 12 10:06:13 raspberrypi systemd[1]: Starting User Manager for UID 999...
Jan 12 10:06:13 raspberrypi systemd[1]: Started Session c32 of user pihole.
Jan 12 10:06:13 raspberrypi systemd[19504]: Reached target Timers.
Jan 12 10:06:13 raspberrypi systemd[19504]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:06:13 raspberrypi systemd[19504]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:06:13 raspberrypi systemd[19504]: Listening on GnuPG cryptographic agent (access for web browsers).
Jan 12 10:06:13 raspberrypi systemd[19504]: Listening on GnuPG cryptographic agent and passphrase cache.
Jan 12 10:06:13 raspberrypi systemd[19504]: Reached target Sockets.
Jan 12 10:06:13 raspberrypi systemd[19504]: Reached target Paths.
Jan 12 10:06:13 raspberrypi systemd[19504]: Reached target Basic System.
Jan 12 10:06:13 raspberrypi systemd[19504]: Reached target Default.
Jan 12 10:06:13 raspberrypi systemd[19504]: Startup finished in 65ms.
Jan 12 10:06:13 raspberrypi systemd[1]: Started User Manager for UID 999.
Jan 12 10:06:15 raspberrypi pihole-FTL[19438]: FTL started!
Jan 12 10:06:15 raspberrypi systemd[1]: Started LSB: pihole-FTL daemon.
Jan 12 10:07:02 raspberrypi kernel: [60472.230944] Alignment trap: not handling instruction e1962f9f at [<76db78f8>]
Jan 12 10:07:02 raspberrypi kernel: [60472.230959] Unhandled fault: alignment exception (0x001) at 0x73756e5f
Jan 12 10:07:02 raspberrypi kernel: [60472.232841] pgd = b6810000
Jan 12 10:07:02 raspberrypi kernel: [60472.234490] [73756e5f] *pgd=00000000
Jan 12 10:07:18 raspberrypi systemd[1]: Stopping LSB: pihole-FTL daemon...
Jan 12 10:07:24 raspberrypi pihole-FTL[19791]: .....
Jan 12 10:07:24 raspberrypi pihole-FTL[19791]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Jan 12 10:07:24 raspberrypi systemd[1]: pihole-FTL.service: Control process exited, code=exited status=1
Jan 12 10:07:24 raspberrypi systemd[1]: Stopped LSB: pihole-FTL daemon.
Jan 12 10:07:24 raspberrypi systemd[1]: pihole-FTL.service: Unit entered failed state.
Jan 12 10:07:24 raspberrypi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Jan 12 10:07:24 raspberrypi systemd[1]: Starting LSB: pihole-FTL daemon...
Jan 12 10:07:24 raspberrypi systemd[1]: Stopping User Manager for UID 999...
Jan 12 10:07:24 raspberrypi systemd[19504]: Stopped target Default.
Jan 12 10:07:24 raspberrypi systemd[19504]: Stopped target Basic System.
Jan 12 10:07:24 raspberrypi systemd[19504]: Stopped target Paths.
Jan 12 10:07:24 raspberrypi systemd[19504]: Stopped target Timers.
Jan 12 10:07:24 raspberrypi systemd[19504]: Stopped target Sockets.
Jan 12 10:07:24 raspberrypi systemd[19504]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:07:24 raspberrypi systemd[19504]: Closed GnuPG cryptographic agent and passphrase cache.
Jan 12 10:07:24 raspberrypi systemd[19504]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:07:24 raspberrypi systemd[19504]: Closed GnuPG cryptographic agent (access for web browsers).
Jan 12 10:07:24 raspberrypi systemd[19504]: Reached target Shutdown.
Jan 12 10:07:24 raspberrypi systemd[19504]: Starting Exit the Session...
Jan 12 10:07:24 raspberrypi systemd[19504]: Received SIGRTMIN+24 from PID 19869 (kill).
Jan 12 10:07:24 raspberrypi systemd[1]: Stopped User Manager for UID 999.
Jan 12 10:07:24 raspberrypi systemd[1]: Removed slice User Slice of pihole.
Jan 12 10:07:24 raspberrypi pihole-FTL[19867]: Not running
Jan 12 10:07:34 raspberrypi systemd[1]: Created slice User Slice of pihole.
Jan 12 10:07:34 raspberrypi systemd[1]: Starting User Manager for UID 999...
Jan 12 10:07:34 raspberrypi systemd[1]: Started Session c33 of user pihole.
Jan 12 10:07:34 raspberrypi systemd[19940]: Listening on GnuPG cryptographic agent and passphrase cache.
Jan 12 10:07:34 raspberrypi systemd[19940]: Listening on GnuPG cryptographic agent (access for web browsers).
Jan 12 10:07:34 raspberrypi systemd[19940]: Reached target Paths.
Jan 12 10:07:34 raspberrypi systemd[19940]: Reached target Timers.
Jan 12 10:07:34 raspberrypi systemd[19940]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:07:34 raspberrypi systemd[19940]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:07:34 raspberrypi systemd[19940]: Reached target Sockets.
Jan 12 10:07:34 raspberrypi systemd[19940]: Reached target Basic System.
Jan 12 10:07:34 raspberrypi systemd[19940]: Reached target Default.
Jan 12 10:07:34 raspberrypi systemd[19940]: Startup finished in 39ms.
Jan 12 10:07:34 raspberrypi systemd[1]: Started User Manager for UID 999.
Jan 12 10:07:35 raspberrypi pihole-FTL[19867]: FTL started!
Jan 12 10:07:35 raspberrypi systemd[1]: Started LSB: pihole-FTL daemon.
Jan 12 10:08:02 raspberrypi kernel: [60532.234609] Alignment trap: not handling instruction e1962f9f at [<76e578f8>]
Jan 12 10:08:02 raspberrypi kernel: [60532.234623] Unhandled fault: alignment exception (0x001) at 0x6c6c615f
Jan 12 10:08:02 raspberrypi kernel: [60532.236439] pgd = 9f004000
Jan 12 10:08:02 raspberrypi kernel: [60532.238100] [6c6c615f] *pgd=00000000
Jan 12 10:08:02 raspberrypi systemd[1]: Stopping User Manager for UID 999...
Jan 12 10:08:02 raspberrypi systemd[19940]: Stopped target Default.
Jan 12 10:08:02 raspberrypi systemd[19940]: Stopped target Basic System.
Jan 12 10:08:02 raspberrypi systemd[19940]: Stopped target Sockets.
Jan 12 10:08:02 raspberrypi systemd[19940]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:08:02 raspberrypi systemd[19940]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:08:02 raspberrypi systemd[19940]: Stopped target Timers.
Jan 12 10:08:02 raspberrypi systemd[19940]: Closed GnuPG cryptographic agent and passphrase cache.
Jan 12 10:08:02 raspberrypi systemd[19940]: Closed GnuPG cryptographic agent (access for web browsers).
Jan 12 10:08:02 raspberrypi systemd[19940]: Reached target Shutdown.
Jan 12 10:08:02 raspberrypi systemd[19940]: Starting Exit the Session...
Jan 12 10:08:02 raspberrypi systemd[19940]: Stopped target Paths.
Jan 12 10:08:02 raspberrypi systemd[19940]: Received SIGRTMIN+24 from PID 19993 (kill).
Jan 12 10:08:03 raspberrypi systemd[1]: Stopped User Manager for UID 999.
Jan 12 10:08:03 raspberrypi systemd[1]: Removed slice User Slice of pihole.
Jan 12 10:09:01 raspberrypi systemd[1]: Starting Clean php session files...
Jan 12 10:09:01 raspberrypi CRON[20030]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 12 10:09:02 raspberrypi systemd[1]: Started Clean php session files.
Jan 12 10:09:14 raspberrypi systemd[1]: Stopping LSB: pihole-FTL daemon...
Jan 12 10:09:14 raspberrypi pihole-FTL[20110]: Not running
Jan 12 10:09:14 raspberrypi systemd[1]: Stopped LSB: pihole-FTL daemon.
Jan 12 10:09:25 raspberrypi systemd[1]: Starting LSB: pihole-FTL daemon...
Jan 12 10:09:25 raspberrypi pihole-FTL[20158]: Not running
Jan 12 10:09:25 raspberrypi systemd[1]: Created slice User Slice of pihole.
Jan 12 10:09:25 raspberrypi systemd[1]: Started Session c34 of user pihole.
Jan 12 10:09:25 raspberrypi systemd[1]: Starting User Manager for UID 999...
Jan 12 10:09:25 raspberrypi systemd[20188]: Reached target Timers.
Jan 12 10:09:25 raspberrypi systemd[20188]: Listening on GnuPG cryptographic agent (access for web browsers).
Jan 12 10:09:25 raspberrypi systemd[20188]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:09:25 raspberrypi systemd[20188]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:09:25 raspberrypi systemd[20188]: Reached target Paths.
Jan 12 10:09:25 raspberrypi systemd[20188]: Listening on GnuPG cryptographic agent and passphrase cache.
Jan 12 10:09:25 raspberrypi systemd[20188]: Reached target Sockets.
Jan 12 10:09:25 raspberrypi systemd[20188]: Reached target Basic System.
Jan 12 10:09:25 raspberrypi systemd[20188]: Reached target Default.
Jan 12 10:09:25 raspberrypi systemd[20188]: Startup finished in 40ms.
Jan 12 10:09:25 raspberrypi systemd[1]: Started User Manager for UID 999.
Jan 12 10:09:26 raspberrypi pihole-FTL[20158]: FTL started!
Jan 12 10:09:26 raspberrypi systemd[1]: Started LSB: pihole-FTL daemon.
Jan 12 10:10:01 raspberrypi kernel: [60650.939424] Alignment trap: not handling instruction e1962f9f at [<76ddb8f8>]
Jan 12 10:10:01 raspberrypi kernel: [60650.939441] Unhandled fault: alignment exception (0x001) at 0x000c27be
Jan 12 10:10:01 raspberrypi kernel: [60650.941261] pgd = b6bbc000
Jan 12 10:10:01 raspberrypi kernel: [60650.942952] [000c27be] *pgd=00000000
Jan 12 10:10:01 raspberrypi CRON[20277]: (root) CMD (   PATH="$PATH:/usr/local/bin/" pihole updatechecker local)
Jan 12 10:11:49 raspberrypi systemd[1]: Stopping LSB: pihole-FTL daemon...
Jan 12 10:11:55 raspberrypi pihole-FTL[20334]: .....
Jan 12 10:11:55 raspberrypi pihole-FTL[20334]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Jan 12 10:11:55 raspberrypi systemd[1]: pihole-FTL.service: Control process exited, code=exited status=1
Jan 12 10:11:55 raspberrypi systemd[1]: Stopped LSB: pihole-FTL daemon.
Jan 12 10:11:55 raspberrypi systemd[1]: pihole-FTL.service: Unit entered failed state.
Jan 12 10:11:55 raspberrypi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Jan 12 10:11:55 raspberrypi systemd[1]: Starting LSB: pihole-FTL daemon...
Jan 12 10:11:55 raspberrypi systemd[1]: Stopping User Manager for UID 999...
Jan 12 10:11:55 raspberrypi systemd[20188]: Stopped target Default.
Jan 12 10:11:55 raspberrypi systemd[20188]: Stopped target Basic System.
Jan 12 10:11:55 raspberrypi systemd[20188]: Stopped target Timers.
Jan 12 10:11:55 raspberrypi systemd[20188]: Stopped target Paths.
Jan 12 10:11:55 raspberrypi systemd[20188]: Stopped target Sockets.
Jan 12 10:11:55 raspberrypi systemd[20188]: Closed GnuPG cryptographic agent and passphrase cache.
Jan 12 10:11:55 raspberrypi systemd[20188]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:11:55 raspberrypi systemd[20188]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:11:55 raspberrypi systemd[20188]: Closed GnuPG cryptographic agent (access for web browsers).
Jan 12 10:11:55 raspberrypi systemd[20188]: Reached target Shutdown.
Jan 12 10:11:55 raspberrypi pihole-FTL[20411]: Not running
Jan 12 10:11:55 raspberrypi systemd[20188]: Starting Exit the Session...
Jan 12 10:11:55 raspberrypi systemd[20188]: Received SIGRTMIN+24 from PID 20414 (kill).
Jan 12 10:11:55 raspberrypi systemd[1]: Stopped User Manager for UID 999.
Jan 12 10:11:55 raspberrypi systemd[1]: Removed slice User Slice of pihole.
Jan 12 10:11:56 raspberrypi kernel: [60765.563979] Under-voltage detected! (0x00050005)
Jan 12 10:12:02 raspberrypi kernel: [60771.803953] Voltage normalised (0x00000000)
Jan 12 10:12:05 raspberrypi systemd[1]: Created slice User Slice of pihole.
Jan 12 10:12:05 raspberrypi systemd[1]: Starting User Manager for UID 999...
Jan 12 10:12:05 raspberrypi systemd[1]: Started Session c35 of user pihole.
Jan 12 10:12:05 raspberrypi systemd[20484]: Listening on GnuPG cryptographic agent (access for web browsers).
Jan 12 10:12:05 raspberrypi systemd[20484]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jan 12 10:12:05 raspberrypi systemd[20484]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jan 12 10:12:05 raspberrypi systemd[20484]: Listening on GnuPG cryptographic agent and passphrase cache.
Jan 12 10:12:05 raspberrypi systemd[20484]: Reached target Timers.
Jan 12 10:12:05 raspberrypi systemd[20484]: Reached target Paths.
Jan 12 10:12:05 raspberrypi systemd[20484]: Reached target Sockets.
Jan 12 10:12:05 raspberrypi systemd[20484]: Reached target Basic System.
Jan 12 10:12:05 raspberrypi systemd[20484]: Reached target Default.
Jan 12 10:12:05 raspberrypi systemd[20484]: Startup finished in 40ms.
Jan 12 10:12:05 raspberrypi systemd[1]: Started User Manager for UID 999.
Jan 12 10:12:06 raspberrypi pihole-FTL[20411]: FTL started!
Jan 12 10:12:06 raspberrypi systemd[1]: Started LSB: pihole-FTL daemon.
Jan 12 10:13:01 raspberrypi kernel: [60830.986542] Alignment trap: not handling instruction e1962f9f at [<76de88f8>]
Jan 12 10:13:01 raspberrypi kernel: [60830.986562] Unhandled fault: alignment exception (0x001) at 0x74697865
Jan 12 10:13:01 raspberrypi kernel: [60830.988458] pgd = b32f0000
Jan 12 10:13:01 raspberrypi kernel: [60830.990258] [74697865] *pgd=00000000

[mmotti]

I don't know if it's too soon to say but it doesn't seem to happen after running sudo pihole checkout ftl release/v4.2

[DL6ER]

Any particular log to be looking through?

Yes, /var/log/pihole-FTL.log would probably be most interesting

I don't know if it's too soon to say but it doesn't seem to happen after running sudo pihole checkout ftl release/v4.2

This is a good thing! So the crash you observe only happens in development and not in the v4.2 release candidate. I'm currently running only the v4.2 release candidate myself to test this version we want to release soon. However, I surely want to extinguish all bugs also in the development version as this will become the v4.3 at some point.

[DL6ER]

@mmotti Some more information from me for you: The difference between release/v4.2 and development isn't that big, currently it's only given by three PRs:

• #451 (only used in debug mode)
• #453 (only used during startup)
• #455 (called once every minute, the bug comes most likely from here)

There isn't a direct correlation between SIGHUP and the code introduced in #455 but it might have to do with name resolution (which is affected both by restarting and also by sending SIGHUP) so a secondary effect might cause trouble here.

[mmotti]

@DL6ER I had looked in pihole-FTL.log earlier and completely overlooked some errors so didn't include it.

Take a look at pihole-FTL.log

Specifically:

2019-01-12 10:30:43.491] Successfully accessed setupVars.conf
[2019-01-12 10:31:36.953] Resizing "/FTL-queries" from 229376 to 458752
[2019-01-12 10:32:00.095] FATAL ERROR: Trying to access queries[4063], but magic byte is 0
[2019-01-12 10:32:00.096]              found in save_to_DB() (database.c:411)
[2019-01-12 10:32:00.096] FATAL ERROR: Trying to access queries[4063], but magic byte is 0
[2019-01-12 10:32:00.096]              found in save_to_DB() (database.c:426)
[2019-01-12 10:32:00.097] FATAL ERROR: Trying to access queries[4064], but magic byte is 0
[2019-01-12 10:32:00.097]              found in save_to_DB() (database.c:411)
[2019-01-12 10:32:00.097] FATAL ERROR: Trying to access queries[4064], but magic byte is 0

Seems to correlate with recent db changes?

Edit: Not sure if these are definitely the cause of the crash as I am still getting them now when things seem to be running OK. I can see from the syslog that the service may have started failing again at 10:04am. I can't see much in the pihole-FTL.log relating to then which is probably why I didn't initially include it, but I am only skim reading.

[DL6ER]

I will have a look at the possible cause for the errors you posted above but I agree that they shouldn't be the cause for the crash. I was hoping for a backtrace in the logs (they are usually generated on crashes) but they aren't there. Could you please follow the instructions described as here?
This will directly show the cause of the issues.

[mmotti]

Sure.

Does this work retrospectively or do I need to switch channels etc again? (haven't looked at link yet)

[DL6ER]

The debugger can be attached to an already running pihole-FTL process.

[mmotti]

OK. After I've had some lunch I'll attach the debugger before switching branches again.

Can I revert back on failure? Will the info remain available?

[DL6ER]

On failure, pihole-FTL will be stopped and the debugger comes into foreground. The information will not be logged anywhere, so you will have to copy&paste it from the debugger output.

You can then checkout a working version and run this one until I may ask you to repeat the crashing process (with some commands to run in the debugger). We can do it like this as you can easily reproduce the crash. Things are much more difficult when crashes are rare and cannot easily be reproduced.

[mmotti]

Would it be easier to give you a team viewer session to my laptop if I manually apply different dns to laptop to prevent loss of Internet access?

I'd only ask that you undo whatever debugging is attached

[DL6ER]

The debugger will only be attached for one session. As soon as you start another instance of pihole-FTL, everything is reverted to normal. I'm traveling right now and cannot promise when I will have time or a sufficiently steady Internet connection, so Teamviewer might not work. I'll only be back on Wednesday evening (central European time).

[mmotti]

Understood. Let me see what I can come up with and I'll get back to you.

[mmotti]

pi@raspberrypi:~ $ sudo gdb -p $(pidof pihole-FTL)
GNU gdb (Raspbian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 28440
[New LWP 28441]
[New LWP 28442]
[New LWP 28443]
[New LWP 28444]
[New LWP 28445]
[New LWP 28446]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
0x76e3fcb0 in poll () at ../sysdeps/unix/syscall-template.S:84
84      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) handle SIGHUP nostop SIGPIPE nostop
Signal        Stop      Print   Pass to program Description
SIGHUP        No        Yes     Yes             Hangup
SIGPIPE       No        Yes     Yes             Broken pipe
(gdb) continue
Continuing.

Thread 5 "database" received signal SIGBUS, Bus error.
[Switching to Thread 0x752c1470 (LWP 28444)]
0x76de58fc in _int_free (av=0x607b69b9, p=0x5942d0, have_lock=0)
    at malloc.c:4000
4000    malloc.c: No such file or directory.
(gdb)

Any help? I'm back on master branch for now until these errors are sorted :-)

[DL6ER]

Thanks! This is already helpful.

When it shows (gdb) after the crash, can you also type where and give the result?

[mmotti]

OK. I'll reproduce the error and update this post. Anything after that or can I stay on working branch?

[DL6ER]

Nothing more for now, I how that the where output will be enough. Probably it won't but I can use it to work from there. It's still possible that these are connected to the database issues you've seen earlier, but let's see.

[mmotti]

@DL6ER

How's this?

Thread 5 "database" received signal SIGBUS, Bus error.
[Switching to Thread 0x7524a470 (LWP 1085)]
0x76d6e8fc in _int_free (av=0x6852d0a7, p=0x5752d0, have_lock=0)
    at malloc.c:4000
4000    malloc.c: No such file or directory.
(gdb) where
#0  0x76d6e8fc in _int_free (av=0x6852d0a7, p=0x5752d0, have_lock=0)
    at malloc.c:4000
#1  0x0049f18a in parse_arp_cache () at networktable.c:144
#2  0x00497af2 in DB_thread (val=<optimized out>) at database.c:635
#3  0x76e45fc4 in start_thread (arg=0x7524a470) at pthread_create.c:335
#4  0x76dd1bc8 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:76
   from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb)

[DL6ER]

Yes, thanks. I'm 99% certain that

sudo pihole checkout ftl fix/arp_free

will solve the issue you're seeing. The reason for this is an incorrect free() on a static string that happens when you don't have the macvendor.db database.

[mmotti]

Good news.

I'll switch to that branch, reboot and see what happens.

[mmotti]

Seems good at the moment. Hopefully it can be applied to dev soon.

[DL6ER]

I'm sure it will get merged as soon as one of the other developers can find the time to review and approve the code. It really is only a minor change.

[mmotti]

Excellent. Thanks for looking at it so quickly

[DL6ER]

463 has been merged.