Unbound-dhcp-leases-bridge not firing correctly

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.

1 Like

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.

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

@mutley great find! :male_detective: :champagne:

@ipfire
is this some very rare specific hardware related ‘feature’? :man_shrugging:
because it seems quite strange that just around two to four ipfire installations/users see this behavior and searching for answers here… :exploding_head:
for my case the few ipfire i monitor do not use the dhcp/dns feature
except the one that brought me here. :hamster:
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 :question: :thinking:
maybe ipfire isn’t made for that, but more for routing/ids/ips/webproxy :grey_question: :man_shrugging:

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!)

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.

1 Like

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

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.

2 Likes

Thanks!

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

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

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.

Still no joy… :frowning_face:

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

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

No joy…
:frowning_face:

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:

to make sure I didn’t accidentally change something…

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

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.

@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.

1 Like