Ftl: dhcp-script not being called in v5.1.2

[GXTracker]

Versions

• Pi-hole: version is v5.1.2 (Latest: v5.1.2)
• AdminLTE: version is v5.1.1 (Latest: v5.1.1)
• FTL: version is v5.2 (Latest: v5.2)

Platform

• OS and version: "Raspbian GNU/Linux 10 (buster)"
  
• Platform: Raspberry Pi 4b 4GB

Expected behavior

Prior to upgrading to v5.1.2, the dhcp-script command would execute a script which it is now not executing.

in /etc/dnsmasq.d there is a file created: 50-dhcp-script.conf with the following content:

# File needs to be placed in /etc/dnsmasq.d/ folder

# Run the following script when a DHCP event occurs
dhcp-script=/home/pihole/autowake.sh

in /etc/home/pihole the following script exists:

#! /bin/bash

# dnsmasq uses the dhcp-script option to run a script on lease change.
# There are 4 paramaters:
# $1 = Add Del Old
# $2 = MAC of leased device
# $3 = IP of leased device
# $4 = Hostname of leased device

#########################
### Set any variables ###
#########################

# Hostnames of computers that will cause the NAS to wake. Use spaces to seperate hostnames.
NAS_CLIENTS='htpc1 htpc2 desktop'

# MAC address of NAS server that will wake up.
NAS_SERVER='XX:XX:XX:XX:XX:XX'

#################
### Functions ###
#################

# Log system notices
logit()
{

    logger -p local0.notice -s -- AutoWake: "$@"
    return 0
}

# Function for NAS wakeup
NASWakeup()
{
    # set the check variables
    CHECK1=0
    CHECK2=0

    # Is it one of the clients in the list?
    for a in $NAS_CLIENTS; do
        if [ "$1" == "$a" ]; then
            CHECK1=1
        fi
    done

    # Only check for DHCP's being added or refreshed
    if [ "$2" == "add" ] || [ "$2" == "old" ]; then
        CHECK2=1
    fi

    # If all critera is met, then issue the WOL command
    if [ $CHECK1 -eq 1 ] && [ $CHECK2 -eq 1 ]; then
        logit "$1 has been turned on: issuing WoL to $NAS_SERVER"
        wakeonlan $NAS_SERVER
    fi

    return 0
}

####################################
### Beginning of the main script ###
####################################
NASWakeup "$4" "$1"
logit "The autowake.sh script has completed successfully"

Actual behavior / bug

because of the logger function in the script, an entry should be put into /var/log/syslog every time the script is run as it did prior to updating to 5.1.2.

presently, the script does not run at all when doing a tail -f on the syslog.

Steps to reproduce

on any machine that is in the NAS_CLIENTS array, perform an IP address flush and renew to trigger the event.

Debug Token

• URL: https://tricorder.pi-hole.net/g7i2srrl5m

Screenshots

N/A

Additional context

N/A

[DL6ER]

Nothing has changed concerning dhcp-script in years (at least nothing I'd be aware of). Maybe it is a permission error somewhere?

Try running

grep "failed to execute" /var/log/pihole.log

---

You could also try calling another dhcp-script that does nothing else than a simple logging, e.g.,

#!/bin/bash
echo "$@" >> /tmp/dhcp-script.log

and check what is happening in /tmp/dhcp-script.log (new lines should be added one after another on DHCP events).

[GXTracker]

Thanks for the response. I ran grep "failed to execute" /var/log/pihole.log and there are no entries in the pihole.log as nothing was returned.

I also created a /home/pihole/test.sh script with your simple logging example, and after changing the line in 50-dhcp-script.conf and restarting the DNS resolver there was no /tmp/dhcp-script.log file created.

any other suggestions to see if dhcp-script is even being called? I know that files in /etc/dnsmasq.d are being called as I have a 51-myhosts.conf file that contains the following:

addn-hosts=/etc/hosts

and I can see that happening in pihole.log as it says that the file is read and 20 entries are added.

[DL6ER]

So the next question is if there is any DHCP activity at all on your Pi-hole or whether, e.g., the router took over. Please add

log-dhcp

to your /etc/dnsmasq.d/50-dhcp-script.conf if you haven't done so already. Then monitor your /var/log/pihole.log for DHCP messages. Are there any? If so, which? And is there still no /tmp/dhcp-script.log being created afterwards?

[GXTracker]

Interesting. I added the log-dhcp line to /etc/dnsmasq.d/50-dhcp-script.conf and then restarted the DNS resolver within the pihole console, and then it created a /tmp/dhcp-script.log file with DHCP entries in there.

so then I commented out the /home/pihole/test.sh line, and uncommented my /home/pihole/autowake.sh script and restarted the DNS resolver again - still not running the script.

I can manually run the script by running sudo -u pihole /home/pihole/autowake.sh as the pihole user and that works. autowake.sh and test.sh have the same file and ownership permissions when performing an ls -la

i then switched the lines back in /etc/dnsmasq.d/50-dhcp-script.conf (commented out /home/pihole/autowake.sh and uncommented /home/pihole/test.sh) and restarted the DNS resolver - now its not working again! after renewing an IP address on a PC on my network, there are no new entries in the /tmp/dhcp-script.log file.

when doing a grep on pihole.log I can see DHCPDISCOVER, DHCPOFFER, DHCPREQUEST, and DHCPACK entries for that PC being generated and its being assigned an IP from the pihole. Very strange.

[DL6ER]

I'm not sure I'm getting this right. So logging to dhcp-script.log worked once but then not again later with the exact same configuration?

[GXTracker]

Nope, you are correct. It worked once, then after restarting the DNS Resolver through Pihole it stopped working...

[DL6ER]

I'm still trying to identify possible causes for what you're seeing but I'm yet unable to trigger a case similar to yours. One furter question: Does pidof pihole-FTL return only one or multiple process IDs?

[GXTracker]

great suggestion - I ran pidof pihole-FTL and got 2 process ID's.

[DL6ER]

2 PIDs is correct (at least when your network is not doing any TCP queries). FTL forks a dedicated script engine early in the process so it's likely that the machinery is set up correctly for you, it just isn't clear why it doesn't work for you.

Please try

pihole checkout ftl master_helper_logs

and then check /var/log/pihole-FTL.log for debug lines:

grep "DEBUG: dnsmasq" /var/log/pihole-FTL.log

(after some DHCP activity)

[GXTracker]

OK done. so I'm seeing DEBUG entries for the test script:

[2020-10-26 12:04:48.797 26994/F26987] DEBUG: dnsmasq helper called for action "del"
[2020-10-26 12:04:48.800 27091/F26987] DEBUG: dnsmasq helper executing "test.sh" with arguments: "del 30:9c:23:e3:78:2e 192.168.1.100 jdsw-desktop"
[2020-10-26 12:04:51.299 26994/F26987] DEBUG: dnsmasq helper called for action "add"
[2020-10-26 12:04:51.302 27092/F26987] DEBUG: dnsmasq helper executing "test.sh" with arguments: "add 30:9c:23:e3:78:2e 192.168.1.100 jdsw-desktop"

and now I'm uncommenting the line in 50-dhcp-script.conf to put my autowake script back in:

# File needs to be placed in /etc/dnsmasq.d/ folder

# Run the following script when a DHCP event occurs
dhcp-script=/home/pihole/autowake.sh
#dhcp-script=/home/pihole/test.sh
#log-dhcp

Restarted the DNS Resolver via the web interface and did an ipconfig /release then ipconfig /renew on my PC and im seeing DEBUG entries now for the autowake.sh script:

[2020-10-26 12:09:22.594 27402/F27394] DEBUG: dnsmasq helper called for action "del"
[2020-10-26 12:09:22.597 27461/F27394] DEBUG: dnsmasq helper executing "autowake.sh" with arguments: "del 30:9c:23:e3:78:2e 192.168.1.100 jdsw-desktop"
[2020-10-26 12:09:25.276 27402/F27394] DEBUG: dnsmasq helper called for action "add"
[2020-10-26 12:09:25.279 27464/F27394] DEBUG: dnsmasq helper executing "autowake.sh" with arguments: "add 30:9c:23:e3:78:2e 192.168.1.100 jdsw-desktop"

and im also seeing entries in my syslog now for the script:

Oct 26 12:09:22 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Oct 26 12:09:25 jdsw-pi pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59

[dschaper]

Could the lua includes cause any of this DL? I think we enabled lua for the interpreter and dnsmasq will use luascripts for DHCP lease firing scripts. I don't think any of the code was changed, but it might be something to pick at.

[DL6ER]

@dschaper No, lua is separate and only for experiments (we don't even have a PR for this). It only lives in https://github.com/pi-hole/FTL/tree/new/lua

@GXTracker Okay, so it is working now without me having done any changes else that a few extra log lines (which do not change the functionality of the remaining code). Is it working reliably now (as in across restarts, etc.)? And does it really stop working again when you go back to the regular version (pihole checkout ftl master)?

[GXTracker]

Yep it seems to be working reliably across several restarts of my Pi, restarts of just the DNS resolver, and I've tested with renewing the IP from various other machines on the network. monitoring with tail -f /var/log/syslog looking for additional entries in real-time:

Oct 26 13:39:15 jdsw-pi pihole: AutoWake: jdsw-xps13 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Oct 26 13:39:15 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully

I then went back to the regular version with pihole checkout ftl master and it worked after the first reboot, but then restarting the DNS Resolver through the Web Interface cause it to stop working again. Definitely looks to be the issue in the master branch.

[DL6ER]

Definitely looks to be the issue in the master branch.

Well, that's not good, because the only change is adding log lines (see here). You can ignore the changes in the two other files (this was only necessary due to updated build system and has no other consequences).

You can stay on the master_helper_logs branch if you like, it is identical to the most recent release, except the additional logging. I will add the additional logging as an optional feature for the future versions of Pi-hole FTL as it seems useful to see what is going on (https://github.com/pi-hole/FTL/pull/914). Yet, it does not really change anything but may help isolating the issue you're facing in the long-run.

[GXTracker]

Thanks for looking into this @DL6ER! I'll switch to the master_helper_logs branch for now as I'm trying to work on a some additional functionality in my script for the WoL feature and having this work reliably would definitely help.

Let me know if there are any additional logs I can provide or commands I can test out for you on my end if you need more assistance with reproducing the issue.

[GXTracker]

Something interesting that I just noticed - I'm still on the master_helper_logs branch, and noticed this morning that my autowake.sh script isn't running. I ran asudo tail -f /var/log/syslog and restarted the DNS resolver, and after doing so the script ran several times, as if the commands were being queued up but not executed for some reason? see below for an excerpt from my syslog:

Nov 16 09:19:42 jdsw-pi systemd[1]: Stopping LSB: pihole-FTL daemon...
Nov 16 09:19:47 jdsw-pi pihole-FTL[28471]: .....
Nov 16 09:19:47 jdsw-pi pihole-FTL[28471]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Nov 16 09:19:47 jdsw-pi systemd[1]: pihole-FTL.service: Control process exited, code=exited, status=1/FAILURE
Nov 16 09:19:47 jdsw-pi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Nov 16 09:19:47 jdsw-pi systemd[1]: Stopped LSB: pihole-FTL daemon.
Nov 16 09:19:47 jdsw-pi systemd[1]: Starting LSB: pihole-FTL daemon...
Nov 16 09:19:47 jdsw-pi systemd[1]: session-c1.scope: Succeeded.
Nov 16 09:19:47 jdsw-pi pihole-FTL[28486]: Stopped
Nov 16 09:19:47 jdsw-pi systemd[1]: Started Session c44 of user pihole.
Nov 16 09:19:48 jdsw-pi pihole-FTL[28486]: FTL started!
Nov 16 09:19:48 jdsw-pi systemd[1]: Started LSB: pihole-FTL daemon.
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: jdsw-htpc1 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: jdsw-xps13 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Nov 16 09:19:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Nov 16 09:19:55 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully

[DL6ER]

@GXTracker Please use pihole checkout master to get back on track. The debug logging output is now included here as well as we just released FTL v5.3.

[GXTracker]

Thanks @DL6ER - I'm back on track and will monitor for a week and will let you know

[GXTracker]

Now that I'm back on master I've been monitoring for several days now and the dhcp-script isnt being called until I restart the DNS Resolver service from the Web Console. When i do while doing a tail -f /var/log/syslog then I can see the the pihole-FTL daemon stop, restart, then spam the syslog with the script:

Dec  9 12:59:42 jdsw-pi systemd[1]: Stopping LSB: pihole-FTL daemon...
Dec  9 12:59:47 jdsw-pi pihole-FTL[26452]: .....
Dec  9 12:59:47 jdsw-pi pihole-FTL[26452]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Dec  9 12:59:47 jdsw-pi systemd[1]: session-c1.scope: Succeeded.
Dec  9 12:59:47 jdsw-pi systemd[1]: pihole-FTL.service: Control process exited, code=exited, status=1/FAILURE
Dec  9 12:59:47 jdsw-pi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Dec  9 12:59:47 jdsw-pi systemd[1]: Stopped LSB: pihole-FTL daemon.
Dec  9 12:59:47 jdsw-pi systemd[1]: Starting LSB: pihole-FTL daemon...
Dec  9 12:59:47 jdsw-pi pihole-FTL[26467]: Not running
Dec  9 12:59:48 jdsw-pi systemd[1]: Started Session c2 of user pihole.
Dec  9 12:59:48 jdsw-pi pihole-FTL[26467]: FTL started!
Dec  9 12:59:48 jdsw-pi systemd[1]: Started LSB: pihole-FTL daemon.
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: jdsw-htpc1 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Dec  9 12:59:48 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully

[dschaper]

The latest version added the lua support for DHCP scripting. Would that be of any help to you?

[giddyhup]

I have the same issue. For me lua is not an option.

[GXTracker]

the dhcp-script command is handy as its the only way I've found to be able to run a bash script whenever a DHCP event occurs. If LUA can allow me to do the same, then just point me at the FTL lua documentation and I'll see if I can achieve similar.

[DL6ER]

The next version of FTL has been released. Please update and run

pihole checkout master

to get back on-track. Thanks for helping us to make Pi-hole better for us all!

If you still have any issues with the script handlers, please reopen this ticket.

[GXTracker]

Currently running FTL v5.6 and it seemed to be working after first updating, but the problem is persisting and the script is not being called when a DHCP event occurs. When i restart the DNS Resolver in the web interface and do a tail -f /var/log/syslog then I can see that its caching and running the script right after one another:

Feb  7 09:30:25 jdsw-pi systemd[1]: Stopping LSB: pihole-FTL daemon...
Feb  7 09:30:30 jdsw-pi pihole-FTL[15719]: .....
Feb  7 09:30:30 jdsw-pi pihole-FTL[15719]: Not stopped; may still be shutting down or shutdown may have failed, killing now
Feb  7 09:30:30 jdsw-pi systemd[1]: pihole-FTL.service: Control process exited, code=exited, status=1/FAILURE
Feb  7 09:30:30 jdsw-pi systemd[1]: pihole-FTL.service: Failed with result 'exit-code'.
Feb  7 09:30:30 jdsw-pi systemd[1]: Stopped LSB: pihole-FTL daemon.
Feb  7 09:30:30 jdsw-pi systemd[1]: session-c1.scope: Succeeded.
Feb  7 09:30:30 jdsw-pi systemd[1]: Starting LSB: pihole-FTL daemon...
Feb  7 09:30:30 jdsw-pi pihole-FTL[15734]: Not running
Feb  7 09:30:31 jdsw-pi systemd[1]: Started Session c2 of user pihole.
Feb  7 09:30:31 jdsw-pi pihole-FTL[15734]: FTL started!
Feb  7 09:30:31 jdsw-pi systemd[1]: Started LSB: pihole-FTL daemon.
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: jdsw-htpc1 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Feb  7 09:30:31 jdsw-pi pihole: AutoWake: The autowake.sh script has completed successfully

[giddyhup]

Can confirm, one of the recent updates killed it. The last time my script had been called in a busy home network was three days ago. DHCP lease duration is set to one hour. @GXTracker, @DL6ER please reopen the issue.

[DL6ER]

This seems to be a general issue with dnsmasq and its helpers. They aren't all that reliable. I'll reopen this issue and we'll find out what is going wrong.

Please add

DEBUG_HELPERS=true

to the file /etc/pihole/pihole-FTL.conf (create if it does not exist) and run

pihole restartdns

There should be additional log lines like Script: Starting helper for action "..." in the log.

Also, there should be some lines like Started dnsmasq helper.

And please check with pidof pihole-FTL if multiple PIDs are returned

[giddyhup]

I did as advised. pidof pihole-FTL returns two PIDs. pihole -t is not greppable.

[DL6ER]

pihole -t is not greppable.

Try to grep both /var/log/pihole.log and /var/log/pihole-FTL.log

[giddyhup]

grep -i helper - nothing in both files.

[DL6ER]

But you still have the dhcp-script=/home/pihole/test.sh (or other script) in place? Then we need also some more log lines from both files, preferably all after a fresh restart of FTL.

[giddyhup]

Yes. Everything is still in place.

> cat /etc/dnsmasq.d/06-dhcp-script.conf
dhcp-script=/home/pi/bin/dhcpupdate.sh

The respective script is also untouched since when it was working.

[GXTracker]

@DL6ER I have done the same - added DEBUG_HELPERS=true and restarted DNS. pidof pihole-FTL also returns 2 PID's. I also performed the same as @giddyhup and performed a grep -i helpers /var/log/pihole.log and nothing is returned.

Scripts are the same and nothing has changed: dhcp-script=/home/pihole/autowake.sh is currently in use. I have that script logging to /var/log/syslog so that I can see when it executes and what task it performs.

When i tail -f /var/log/pihole.log this is what I see after restarting DNS:

Feb  8 14:19:43 dnsmasq[5935]: exiting on receipt of SIGTERM
Feb  8 14:19:44 dnsmasq[6240]: started, version pi-hole-2.84 cachesize 10000
Feb  8 14:19:44 dnsmasq[6240]: compile time options: IPv6 GNU-getopt no-DBus no-UBus no-i18n IDN DHCP DHCPv6 Lua TFTP no-conntrack ipset auth cryptohash DNSSEC loop-detect inotify dumpfile
Feb  8 14:19:44 dnsmasq-dhcp[6240]: DHCP, IP range 192.168.1.200 -- 192.168.1.250, lease time 12h
Feb  8 14:19:44 dnsmasq[6240]: using only locally-known addresses for domain jdsw.local
Feb  8 14:19:44 dnsmasq[6240]: using only locally-known addresses for domain use-application-dns.net
Feb  8 14:19:44 dnsmasq[6240]: using nameserver 127.0.0.1#5335
Feb  8 14:19:44 dnsmasq[6240]: read /etc/hosts - 20 addresses
Feb  8 14:19:44 dnsmasq[6240]: read /etc/hosts - 20 addresses
Feb  8 14:19:44 dnsmasq[6240]: read /etc/pihole/custom.list - 0 addresses
Feb  8 14:19:44 dnsmasq[6240]: read /etc/pihole/local.list - 2 addresses
Feb  8 14:19:44 dnsmasq-script[6240]: <133>Feb  8 14:19:44 pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Feb  8 14:19:44 dnsmasq-script[6240]: Sending magic packet to 255.255.255.255:9 with 50:E5:49:BF:F4:59
Feb  8 14:19:44 dnsmasq-script[6240]: <133>Feb  8 14:19:44 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:44 dnsmasq-script[6240]: <133>Feb  8 14:19:44 pihole: AutoWake: jdsw-desktop has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Feb  8 14:19:45 dnsmasq-script[6240]: Sending magic packet to 255.255.255.255:9 with 50:E5:49:BF:F4:59
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: jdsw-htpc1 has been turned on: issuing WoL to 50:E5:49:BF:F4:59
Feb  8 14:19:45 dnsmasq-script[6240]: Sending magic packet to 255.255.255.255:9 with 50:E5:49:BF:F4:59
Feb  8 14:19:45 dnsmasq-script[6240]: <133>Feb  8 14:19:45 pihole: AutoWake: The autowake.sh script has completed successfully

notice the rapidfire dnsmasq-script[6420] entries in there calling the script repeatedly after the service starts. That's interesting.

[DL6ER]

My memory tricked me. It is

DEBUG_HELPER

without a trailing S. Sorry for that! So up to another round.

notice the rapidfire dnsmasq-script[6420] entries in there calling the script repeatedly after the service starts. That's interesting.

However it shows that something is working. The correct debug option should reveal more in pihole-FTL.log now.

[giddyhup]

OK. Script is being executed (only for 'old'?)
Edit: grepped again, 'add' shows up, too.

> grep -i "helper" /var/log/pihole-FTL.log
[2021-02-09 08:48:39.790 9821M] * DEBUG_HELPER          YES *
[2021-02-09 08:48:41.668 9830/F9823] Started dnsmasq helper
[2021-02-09 08:48:41.672 9823M] * DEBUG_HELPER          YES *
[2021-02-09 08:48:41.681 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.728 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.768 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.856 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.892 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.927 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.963 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:41.997 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.032 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.068 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.102 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.136 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.170 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.249 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.283 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.318 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.353 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.387 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.426 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.460 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.494 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.529 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.564 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.597 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.632 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.665 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.699 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.734 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.769 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.804 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.837 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.880 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.931 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:42.981 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.030 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.072 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.105 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.139 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.174 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.208 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.243 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.277 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.310 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.345 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.379 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.413 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.447 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.481 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.515 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.549 9830/F9823] Script: Starting helper for action "old"
[2021-02-09 08:48:43.584 9830/F9823] Script: Starting helper for action "old"

[GXTracker]

OK I fixed the DEBUG_HELPERS=true line and restarted the DNS service through the web interface.

unlike @giddyhup I did a grep -i helper /var/log/pihole-FTL.log and I'm not seeing any Script entries when renewing the IP address of a machine:

 $ sudo grep -i helper /var/log/pihole-FTL.log
[2021-02-09 17:15:11.995 24585M] * DEBUG_HELPER          YES *
[2021-02-09 17:15:12.160 24587M] * DEBUG_HELPER          YES *

[GXTracker]

I stand corrected - I performed a sudo pihole restartdns and now see the following:
$ sudo grep -i helper /var/log/pihole-FTL.log [2021-02-09 17:15:11.995 24585M] * DEBUG_HELPER YES * [2021-02-09 17:15:12.160 24587M] * DEBUG_HELPER YES * [2021-02-09 17:21:46.761 24778M] * DEBUG_HELPER YES * [2021-02-09 17:21:46.927 24787/F24780] Started dnsmasq helper [2021-02-09 17:21:46.930 24780M] * DEBUG_HELPER YES * [2021-02-09 17:21:46.931 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.003 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.077 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.089 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.102 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.115 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.129 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.141 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.154 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.167 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.179 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.192 24787/F24780] Script: Starting helper for action "old" [2021-02-09 17:21:47.261 24787/F24780] Script: Starting helper for action "old"

[giddyhup]

It seems to me that currently everything's working as it should be. The MQTT messages that my script is sending keep coming in.

[DL6ER]

While looking at something else, I found a small issue with helpers may having lead to deadlocking when they wanted to log something. Please try if

pihole checkout ftl fix/test_crash

shows an improvement for you.

[Lionel642]

Hi;

same issue here, it was working, I reorganized my scripts, and not working anymore, rolled back and now it's working, a string length issue maybe?
not working with : dhcp-script=/data/lionel/bin/admin/pubDHCP2MQTT.sh
working fine with : dhcp-script=/data/lionel/bin/pubDHCP2MQTT.sh

(still using v 5.2.2, both paths are good, actually symlinks to the same file)

Regards;
Lionel

[DL6ER]

@Lionel642 Plesse try https://github.com/pi-hole/FTL/issues/906#issuecomment-780831109

The string length idea is a good one, however, I do rather think it's a random issue and what you observed may just be coincidence. We will see...

[GXTracker]

While looking at something else, I found a small issue with helpers may having lead to deadlocking when they wanted to log something. Please try if

pihole checkout ftl fix/test_crash

shows an improvement for you.

So far this seems to be working for me. I did not make any changes to my WOL script or any paths and it seems to be functioning as it used to.

[DL6ER]

Thanks for coming back to us! the fix has already been merged and will be part of the next release of FTL.

[DL6ER]

The next version of FTL has been released. Please update and run

pihole checkout master

to get back on-track if you switched to a custom branch. The fix/feature branch you switched to will not receive any further updates.

Thanks for helping us to make Pi-hole better for us all!

If you have any issues, please either reopen this ticket or (preferably) create a new ticket describing the issues in further detail and only reference this ticket. This will help us to help you best.