Unbound-dhcp-leases-bridge not firing correctly

mutley · 11 January 2022 20:05

This is somewhat related to this topic DHCP hosts not reliably propagated to DNS - #38 by current_user, but there is a distinction, so starting a new thread. Please move if appropriate.

I noticed with the Core Update 162, the script /usr/sbin/unbound-dhcp-leases-bridge which updates local machine name resolution, only get’s fired on the first update of any files it’s monitoring, not on any subsequent updates to the files. This might be a python2 vs python3 issue on the inotify library (since that’s the change on this script between my last Core version and this Core 162 version).

Anyway for me it seems the inotify trigger event changes after the first file update. So a simple change to that script on line 103 from.
if "IN_MODIFY" in type_names:
to
if "IN_MODIFY" in type_names or "IN_CLOSE_WRITE" in type_names or "IN_DELETE_SELF" in type_names:

Seems to make sure the script get’s fired on file changes to any of the files it’s monitoring after the initial even has fired.

bonnietwin · 11 January 2022 20:43

Hi @mutley

Welcome to the IPFire community.

python-inotify was changed to python3-inotify in Core Update 157. The final programs using python2 were modified in Core Update 160, such as freeradius, ca-certificates, crda.
Then python2 was removed in Core Update 161.

If that matches up with the effect you are seeing then you should raise a bug on this.

https://wiki.ipfire.org/devel/bugzilla
https://bugzilla.ipfire.org/

Your IPFire People login email address and password also work to log you in on the IPFire bugzilla.

mutley · 11 January 2022 21:49

Thanks, after searching / reading the bug report here. (which is a lot cleaner than the posts in the thread I linked in my first post). I believe this is the issue to the problem others are seeing in that report.

The “IN_DELETE_SELF” & “IN_CLOSE_WRITE” events are actually getting fired on a DNS entry, but the script is expecting “IN_MODIFY” event for both DNS addition and DNS modification. At least that’s what my system seems to be doing.

And yes, I did update from 156 to 161

current_user · 11 January 2022 22:34

@mutley great find!

@ipfire
is this some very rare specific hardware related ‘feature’?
because it seems quite strange that just around two to four ipfire installations/users see this behavior and searching for answers here…
for my case the few ipfire i monitor do not use the dhcp/dns feature
except the one that brought me here.
unfortunately this one had major changes in network-design including
the need of local dns and dhcp resources. now it seems that these
functions are not working well and very few report here about it.
is it a good idea to let ipfire handle dhcp/dns
maybe ipfire isn’t made for that, but more for routing/ids/ips/webproxy

jon · 11 January 2022 22:48

I am curious - How did you monitor the output of Inotify and view the “IN_DELETE_SELF” & “IN_CLOSE_WRITE” event results? (I am looking for your troubleshooting technique!)

mutley · 11 January 2022 22:53

It could well be hardware specific. I haven’t looked at the kernel and inotify in years (probably 15~20), but I do remember it being a PITA. ie you could use the same kernel on and IDE drive and everything was fine, but on at ATA drive inotify wouldn’t fire, or fire events you were not expecting. Of course now there are so many different drive types (ie controllers), and virtual drives, it could well be specific to hardware.

As for dhcp and dns. I fully believe this should be core functionality of ipfire. The problems I see is this was native functionality to dnsmasq (with the correct config), but when ipfire moved away from dnsmasq to unbound a few years ago linking dns to unbound wasn’t natively supported, so ipfire dev team had to write a script to make it work. I think now it is natively supported unbound, so probably just a version and timing issue for the dev team as to when they can throw this script away.

current_user · 11 January 2022 22:58

good description, thank you.
so one has to watch the changelog and the leasefile for now

mutley · 11 January 2022 23:00

When I saw it wasn’t being fired correctly. I simply wrote my own python script copying ipfire’s code around how they implemented inotify. Then read the python documentation on inotify, then added a print statement to print out each event that was fired. Then went through anything I knew that would change the files being monitored (ie web ui changes to hosts & fixed leases, requesting new dns, requesting updating dns from machines) and simply monitored the events that got fired. As an extra, I also triggered file changes with bash commands like touch and vi.

What’s strange is I would expected to have to re-add a inotify listener after the “IN_DELETE_SELF” event, but on my system it workes without having to do that.

jon · 11 January 2022 23:10

Thanks!

I was trying to add log.info(" ") statements in here:

github.com

ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge#L78-L115

    
      
          	def run(self):
          		log.info("Unbound DHCP Leases Bridge started on %s" % self.leases_file)
          		self.running = True
          
          
		# Initial setup
          		self.hosts = self.read_static_hosts()
          		self.update_dhcp_leases()
          
          
		i = inotify.adapters.Inotify([
          			self.leases_file,
          			self.fix_leases_file,
          			self.hosts_file,
          		])
          
          
		for event in i.event_gen():
          			# End if we are requested to terminate
          			if not self.running:
          				break
          
          
			if event is None:

This file has been truncated. show original

…near Line 93. But my python-fu is non-existent!

mutley · 11 January 2022 23:25

if you use log.info then you will need to increase the verbose flag when the script starts. so either edit /etc/init.d/dhcp and add -vvv to the command line for unbound-dhcp-leases-bridge. (then restart the dhcp server) Or run it manually.

jon · 12 January 2022 19:46

Still no joy…

I have the verbose command enabled and I see the text from the log.info command. But not data about event.

log.info("UDLB_Debug - theEvent: %s" % event)

produces this in the message log:

Jan 12 13:33:48 ipfire dhcp[12207]: UDLB_Debug - theEvent: None

So I see the None results but I never see the IN_DELETE_SELF & IN_CLOSE_WRITE event results.

So I am guessing something is different with event and with type_names. (it is probably not a string). This is my lack of python3 knowledge…

for event in i.event_gen():
		log.info("UDLB_Debug - theEvent: %s" % event)				#  <-- Jon added
		# End if we are requested to terminate
		if not self.running:
				break

		if event is None:
				continue

		header, type_names, watch_path, filename = event
		log.info("UDLB_Debug2 - theType_names: %s" % type_names)	#  <-- Jon added
		# Update leases after leases file has been modified

mutley · 12 January 2022 21:41

Take the first (log.info event) out, as that’s trying to print an object. (or you should format that correctly).
On your next log.info line try this code.

log.info("WD=(%d) MASK=(%d) LEN=(%d) MASK->NAMES=%s FILENAME=[%s]", header.wd, header.mask, header.len, type_names, filename)

Don’t forget to restart the script, so /etc/init.d/dhcp restart if you are using everything default. Then you should see this in the logs when you trigger any file changes. But remember you will see a different set of events depending on how the source program is actually modifying the file, the below of from using standard touch command.

Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(32) LEN=(0) MASK->NAMES=['IN_OPEN'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(4) LEN=(0) MASK->NAMES=['IN_ATTRIB'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(8) LEN=(0) MASK->NAMES=['IN_CLOSE_WRITE'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: Reading static hosts from /var/ipfire/main/hosts
Jan 12 15:35:11 adventurer dhcp[573]: Reading DHCP leases from /var/state/dhcp/dhcpd.leases
Jan 12 15:35:11 adventurer dhcp[573]: Reading fix leases from /var/ipfire/dhcp/fixleases
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(32) LEN=(0) MASK->NAMES=['IN_OPEN'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(1) LEN=(0) MASK->NAMES=['IN_ACCESS'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(16) LEN=(0) MASK->NAMES=['IN_CLOSE_NOWRITE'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(1) MASK=(32) LEN=(0) MASK->NAMES=['IN_OPEN'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(1) MASK=(1) LEN=(0) MASK->NAMES=['IN_ACCESS'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(1) MASK=(16) LEN=(0) MASK->NAMES=['IN_CLOSE_NOWRITE'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(2) MASK=(32) LEN=(0) MASK->NAMES=['IN_OPEN'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(2) MASK=(1) LEN=(0) MASK->NAMES=['IN_ACCESS'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(32) LEN=(0) MASK->NAMES=['IN_OPEN'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(1) LEN=(0) MASK->NAMES=['IN_ACCESS'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(3) MASK=(16) LEN=(0) MASK->NAMES=['IN_CLOSE_NOWRITE'] FILENAME=[]
Jan 12 15:35:11 adventurer dhcp[573]: WD=(2) MASK=(16) LEN=(0) MASK->NAMES=['IN_CLOSE_NOWRITE'] FILENAME=[]

So I suggest your code example looks like this

for event in i.event_gen():
		# End if we are requested to terminate
		if not self.running:
				break

		if event is None:
				continue

		header, type_names, watch_path, filename = event
		log.info("WD=(%d) MASK=(%d) LEN=(%d) MASK->NAMES=%s FILENAME=[%s]", 
                             header.wd, header.mask, header.len, type_names, filename)
		# Update leases after leases file has been modified

jon · 12 January 2022 22:55

No joy…

I don’t think I am getting past the the if event test and continue:

if event is None:
	continue

I added a simple

if event is None:
	continue

log.info("got here")

header, type_names, watch_path, filename = event

and it never makes it that far…

Yes, I do this after any change.

I am going to revert back to the original unbound-dhcp-leases-bridge file:

github.com

ipfire/ipfire-2.x/blob/master/config/unbound/unbound-dhcp-leases-bridge

#!/usr/bin/python3
###############################################################################
#                                                                             #
# IPFire.org - A linux based firewall                                         #
# Copyright (C) 2016  Michael Tremer                                          #
#                                                                             #
# This program is free software: you can redistribute it and/or modify        #
# it under the terms of the GNU General Public License as published by        #
# the Free Software Foundation, either version 3 of the License, or           #
# (at your option) any later version.                                         #
#                                                                             #
# This program is distributed in the hope that it will be useful,             #
# but WITHOUT ANY WARRANTY; without even the implied warranty of              #
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the               #
# GNU General Public License for more details.                                #
#                                                                             #
# You should have received a copy of the GNU General Public License           #
# along with this program.  If not, see <http://www.gnu.org/licenses/>.       #
#                                                                             #
###############################################################################

This file has been truncated. show original

to make sure I didn’t accidentally change something…

jon · 13 January 2022 01:24

Now I am moving forward! Something didnt make sense and copying a new unbound-dhcp-leases-bridge file made everything start working! Yay!

jon · 13 January 2022 22:44

My monitoring is up and running. Big THANK YOU for your code & help!!

Were you able to locate this?

What happens that causes this event? I’ve only seen one of these in the past day but I can not determine what causes it.

mutley · 14 January 2022 01:48

@jon No I haven’t had chance/time on #1. But very quick search seems most other firewalls using unbound are doing something very similar to ipfire in this area, so I was probably wrong. But I will look more and post if I find anything.

On self-delete, I’m not sure and without going over the source code for everything that modifys the files (dhcpd and ipfires web scripts) I’ll doubt I’ll ever know. Even if I do find out why, it still needs to be caught and acted on. But my guess would be some form of memory cache of the file expired so it gets rewritten rather that appended. So that’s probably dncpd.

jon · 29 August 2022 14:22

A post was split to a new topic: Still experiencing issues with Unbound-dhcp-leases-bridge

jon · 29 August 2022 14:23

Please see:

This works very well for me! Any add to my small network causes DNS to update. I can ping new machines (by name) instantly.

Thank you to Anthony & Michael and many others!