[PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Anthony Heading]

[-- Attachment #1: Type: text/plain, Size: 2667 bytes --]

Switch from inotify watching individual files to monitoring the
containing directories, as because dhcpd renames its leases file into a
backup, monitoring the single inode does not work well.  Additionally,
python appears to have a bug with replacing expired inotify watches on
single files.
---
 unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
 1 file changed, 31 insertions(+), 16 deletions(-)

diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
index a2df5f1..6e22066 100644
--- unbound-dhcp-leases-bridge
+++ unbound-dhcp-leases-bridge
@@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
 		self.fix_leases_file = fix_leases_file
 		self.hosts_file = hosts_file
 
+		# base mask for a completed file change
+		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
+		# IN_MODIFY since dhcpd appends lease updates to an open file
+		self.watches = {
+		    self.leases_file: mask | inotify.constants.IN_MODIFY,
+		    self.fix_leases_file: mask,
+		    self.hosts_file: mask
+		}
+
 		self.unbound = UnboundConfigWriter(unbound_leases_file)
 		self.running = False
 
@@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
 		self.running = True
 
 		# Initial setup
-		self.hosts = self.read_static_hosts()
-		self.update_dhcp_leases()
+		update_hosts = True
+		update_leases = True
+
+		i = inotify.adapters.Inotify()
 
-		i = inotify.adapters.Inotify([
-			self.leases_file,
-			self.fix_leases_file,
-			self.hosts_file,
-		])
+		for f in self.watches:
+			i.add_watch(os.path.dirname(f), self.watches[f])
 
 		for event in i.event_gen():
 			# End if we are requested to terminate
 			if not self.running:
 				break
 
+			# Make pending updates once inotify queue is empty
 			if event is None:
+				if update_hosts:
+					self.hosts = self.read_static_hosts()
+					update_hosts = False
+				if update_leases:
+					self.update_dhcp_leases()
+					update_leases = False
 				continue
 
 			header, type_names, watch_path, filename = event
 
-			# Update leases after leases file has been modified
-			if "IN_MODIFY" in type_names:
-				# Reload hosts
-				if watch_path == self.hosts_file:
-					self.hosts = self.read_static_hosts()
+			file = os.path.join(watch_path, filename)
+
+			if not file in self.watches:
+				continue
+
+			log.debug("Inotify %s: %s", file, " ".join(type_names))
 
-				self.update_dhcp_leases()
+			update_leases = True
 
-			# If the file is deleted, we re-add the watcher
-			if "IN_IGNORED" in type_names:
-				i.add_watch(watch_path)
+			if file == self.hosts_file:
+				update_hosts = True
 
 		log.info("Unbound DHCP Leases Bridge terminated")
 
-- 
2.34.1

[PATCH 2/3] unbound-dhcp-leases-bridge : read settings less enthusiastically

[Anthony Heading]

[-- Attachment #1: Type: text/plain, Size: 2739 bytes --]

The script is rereading the ethernet and dhcp settings files for every
lease in every update.  Since dhcpd does not have a reload mechanism and
is just restarted for settings changes, and so this bridge is restarted
too, it seems fine just to read these at startup.
---
 unbound-dhcp-leases-bridge | 69 ++++++++++++++++++++------------------
 1 file changed, 36 insertions(+), 33 deletions(-)

diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
index 6e22066..814cf0c 100644
--- unbound-dhcp-leases-bridge
+++ unbound-dhcp-leases-bridge
@@ -329,6 +329,42 @@ class FixLeases(object):
 
 		return leases
 
+def read_settings(filename):
+	settings = {}
+
+	with open(filename) as f:
+		for line in f.readlines():
+			# Remove line-breaks
+			line = line.rstrip()
+
+			k, v = line.split("=", 1)
+			settings[k] = v
+
+	return settings
+
+def load_subnets():
+	# Load ethernet settings
+	ethernet_settings = read_settings("/var/ipfire/ethernet/settings")
+
+	# Load DHCP settings
+	dhcp_settings = read_settings("/var/ipfire/dhcp/settings")
+
+	subnets = {}
+	for zone in ("GREEN", "BLUE"):
+		if not dhcp_settings.get("ENABLE_%s" % zone) == "on":
+			continue
+
+		netaddr = ethernet_settings.get("%s_NETADDRESS" % zone)
+		submask = ethernet_settings.get("%s_NETMASK" % zone)
+
+		subnet = ipaddress.ip_network("%s/%s" % (netaddr, submask))
+		domain = dhcp_settings.get("DOMAIN_NAME_%s" % zone)
+
+		subnets[subnet] = domain
+
+	return subnets
+
+subnets = load_subnets()
 
 class Lease(object):
 	def __init__(self, ipaddr, properties):
@@ -396,25 +432,6 @@ class Lease(object):
 
 	@property
 	def domain(self):
-		# Load ethernet settings
-		ethernet_settings = self.read_settings("/var/ipfire/ethernet/settings")
-
-		# Load DHCP settings
-		dhcp_settings = self.read_settings("/var/ipfire/dhcp/settings")
-
-		subnets = {}
-		for zone in ("GREEN", "BLUE"):
-			if not dhcp_settings.get("ENABLE_%s" % zone) == "on":
-				continue
-
-			netaddr = ethernet_settings.get("%s_NETADDRESS" % zone)
-			submask = ethernet_settings.get("%s_NETMASK" % zone)
-
-			subnet = ipaddress.ip_network("%s/%s" % (netaddr, submask))
-			domain = dhcp_settings.get("DOMAIN_NAME_%s" % zone)
-
-			subnets[subnet] = domain
-
 		address = ipaddress.ip_address(self.ipaddr)
 
 		for subnet in subnets:
@@ -424,20 +441,6 @@ class Lease(object):
 		# Fall back to localdomain if no match could be found
 		return "localdomain"
 
-	@staticmethod
-	def read_settings(filename):
-		settings = {}
-
-		with open(filename) as f:
-			for line in f.readlines():
-				# Remove line-breaks
-				line = line.rstrip()
-
-				k, v = line.split("=", 1)
-				settings[k] = v
-
-		return settings
-
 	@property
 	def fqdn(self):
 		if self.hostname:
-- 
2.34.1

[PATCH 3/3] unbound-dhcp-leases-bridge : minor logging improvements

[Anthony Heading]

[-- Attachment #1: Type: text/plain, Size: 1822 bytes --]

Minor tweaks to logging which were helpful while debugging, including
logging to stderr when running in foreground.
---
 unbound-dhcp-leases-bridge | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
index 814cf0c..17a00f6 100644
--- unbound-dhcp-leases-bridge
+++ unbound-dhcp-leases-bridge
@@ -26,6 +26,7 @@ import ipaddress
 import logging
 import logging.handlers
 import os
+import sys
 import re
 import signal
 import stat
@@ -36,22 +37,21 @@ import inotify.adapters
 
 LOCAL_TTL = 60
 
+log = logging.getLogger("dhcp-bridge")
+
 def setup_logging(loglevel=logging.INFO):
-	log = logging.getLogger("dhcp")
 	log.setLevel(loglevel)
-
-	handler = logging.handlers.SysLogHandler(address="/dev/log", facility="daemon")
+	if args.daemon:
+		handler = logging.handlers.SysLogHandler(address="/dev/log", facility="daemon")
+	else:
+		handler = logging.StreamHandler(sys.stderr)
 	handler.setLevel(loglevel)
 
-	formatter = logging.Formatter("%(name)s[%(process)d]: %(message)s")
+	formatter = logging.Formatter("%(name)s: %(message)s")
 	handler.setFormatter(formatter)
 
 	log.addHandler(handler)
 
-	return log
-
-log = logging.getLogger("dhcp")
-
 def ip_address_to_reverse_pointer(address):
 	parts = address.split(".")
 	parts.reverse()
@@ -602,7 +602,7 @@ if __name__ == "__main__":
 	bridge = UnboundDHCPLeasesBridge(args.dhcp_leases, args.fix_leases,
 		args.unbound_leases, args.hosts)
 
-	ctx = daemon.DaemonContext(detach_process=args.daemon)
+	ctx = daemon.DaemonContext(detach_process=args.daemon, stderr=(None if args.daemon else sys.stderr))
 	ctx.signal_map = {
 		signal.SIGHUP  : bridge.update_dhcp_leases,
 		signal.SIGTERM : bridge.terminate,
-- 
2.34.1

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Michael Tremer]

[-- Attachment #1: Type: text/plain, Size: 3387 bytes --]

Hello Anthony,

Thank you very much for submitting this patch and welcome to the list.

I understand that it is easier to track any changes in the directory, but I don’t quite understand why the logic had to be changed that the changes will be applied at the end only.

Is this just to avoid that multiple updates happen one after the other or what are you trying to achieve?

-Michael

> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
> 
> Switch from inotify watching individual files to monitoring the
> containing directories, as because dhcpd renames its leases file into a
> backup, monitoring the single inode does not work well.  Additionally,
> python appears to have a bug with replacing expired inotify watches on
> single files.
> ---
> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
> 1 file changed, 31 insertions(+), 16 deletions(-)
> 
> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
> index a2df5f1..6e22066 100644
> --- unbound-dhcp-leases-bridge
> +++ unbound-dhcp-leases-bridge
> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
> 		self.fix_leases_file = fix_leases_file
> 		self.hosts_file = hosts_file
> 
> +		# base mask for a completed file change
> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
> +		# IN_MODIFY since dhcpd appends lease updates to an open file
> +		self.watches = {
> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
> +		    self.fix_leases_file: mask,
> +		    self.hosts_file: mask
> +		}
> +
> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
> 		self.running = False
> 
> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
> 		self.running = True
> 
> 		# Initial setup
> -		self.hosts = self.read_static_hosts()
> -		self.update_dhcp_leases()
> +		update_hosts = True
> +		update_leases = True
> +
> +		i = inotify.adapters.Inotify()
> 
> -		i = inotify.adapters.Inotify([
> -			self.leases_file,
> -			self.fix_leases_file,
> -			self.hosts_file,
> -		])
> +		for f in self.watches:
> +			i.add_watch(os.path.dirname(f), self.watches[f])
> 
> 		for event in i.event_gen():
> 			# End if we are requested to terminate
> 			if not self.running:
> 				break
> 
> +			# Make pending updates once inotify queue is empty
> 			if event is None:
> +				if update_hosts:
> +					self.hosts = self.read_static_hosts()
> +					update_hosts = False
> +				if update_leases:
> +					self.update_dhcp_leases()
> +					update_leases = False
> 				continue
> 
> 			header, type_names, watch_path, filename = event
> 
> -			# Update leases after leases file has been modified
> -			if "IN_MODIFY" in type_names:
> -				# Reload hosts
> -				if watch_path == self.hosts_file:
> -					self.hosts = self.read_static_hosts()
> +			file = os.path.join(watch_path, filename)
> +
> +			if not file in self.watches:
> +				continue
> +
> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
> 
> -				self.update_dhcp_leases()
> +			update_leases = True
> 
> -			# If the file is deleted, we re-add the watcher
> -			if "IN_IGNORED" in type_names:
> -				i.add_watch(watch_path)
> +			if file == self.hosts_file:
> +				update_hosts = True
> 
> 		log.info("Unbound DHCP Leases Bridge terminated")
> 
> -- 
> 2.34.1
> 

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Anthony Heading]

[-- Attachment #1: Type: text/plain, Size: 4142 bytes --]

Hello Michael,

That was exactly it, just sidestepping an intuitive race with dhcpd writing.  Somewhat hypothetical why that would happen, e.g. clustered updates for multiple NICs or whatever similar non-atomicity,  but it was easy to express that way,  put the update logic in one place (including the initial one at startup), and made the event timestamps sequences a little easier to follow when it wasn't clear why the updates were getting lost at all.  I thought the boolean variables helped document the admittedly simple logic too.   But none of that is critical.

A

On Mon, Mar 28, 2022, at 1:00 PM, Michael Tremer wrote:
> Hello Anthony,
>
> Thank you very much for submitting this patch and welcome to the list.
>
> I understand that it is easier to track any changes in the directory, 
> but I don’t quite understand why the logic had to be changed that the 
> changes will be applied at the end only.
>
> Is this just to avoid that multiple updates happen one after the other 
> or what are you trying to achieve?
>
> -Michael
>
>> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
>> 
>> Switch from inotify watching individual files to monitoring the
>> containing directories, as because dhcpd renames its leases file into a
>> backup, monitoring the single inode does not work well.  Additionally,
>> python appears to have a bug with replacing expired inotify watches on
>> single files.
>> ---
>> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
>> 1 file changed, 31 insertions(+), 16 deletions(-)
>> 
>> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
>> index a2df5f1..6e22066 100644
>> --- unbound-dhcp-leases-bridge
>> +++ unbound-dhcp-leases-bridge
>> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
>> 		self.fix_leases_file = fix_leases_file
>> 		self.hosts_file = hosts_file
>> 
>> +		# base mask for a completed file change
>> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
>> +		# IN_MODIFY since dhcpd appends lease updates to an open file
>> +		self.watches = {
>> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
>> +		    self.fix_leases_file: mask,
>> +		    self.hosts_file: mask
>> +		}
>> +
>> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
>> 		self.running = False
>> 
>> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
>> 		self.running = True
>> 
>> 		# Initial setup
>> -		self.hosts = self.read_static_hosts()
>> -		self.update_dhcp_leases()
>> +		update_hosts = True
>> +		update_leases = True
>> +
>> +		i = inotify.adapters.Inotify()
>> 
>> -		i = inotify.adapters.Inotify([
>> -			self.leases_file,
>> -			self.fix_leases_file,
>> -			self.hosts_file,
>> -		])
>> +		for f in self.watches:
>> +			i.add_watch(os.path.dirname(f), self.watches[f])
>> 
>> 		for event in i.event_gen():
>> 			# End if we are requested to terminate
>> 			if not self.running:
>> 				break
>> 
>> +			# Make pending updates once inotify queue is empty
>> 			if event is None:
>> +				if update_hosts:
>> +					self.hosts = self.read_static_hosts()
>> +					update_hosts = False
>> +				if update_leases:
>> +					self.update_dhcp_leases()
>> +					update_leases = False
>> 				continue
>> 
>> 			header, type_names, watch_path, filename = event
>> 
>> -			# Update leases after leases file has been modified
>> -			if "IN_MODIFY" in type_names:
>> -				# Reload hosts
>> -				if watch_path == self.hosts_file:
>> -					self.hosts = self.read_static_hosts()
>> +			file = os.path.join(watch_path, filename)
>> +
>> +			if not file in self.watches:
>> +				continue
>> +
>> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
>> 
>> -				self.update_dhcp_leases()
>> +			update_leases = True
>> 
>> -			# If the file is deleted, we re-add the watcher
>> -			if "IN_IGNORED" in type_names:
>> -				i.add_watch(watch_path)
>> +			if file == self.hosts_file:
>> +				update_hosts = True
>> 
>> 		log.info("Unbound DHCP Leases Bridge terminated")
>> 
>> -- 
>> 2.34.1
>>

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Michael Tremer]

[-- Attachment #1: Type: text/plain, Size: 4990 bytes --]

Hello,

> On 28 Mar 2022, at 20:55, Anthony Heading <ajrh(a)ajrh.net> wrote:
> 
> Hello Michael,
> 
> That was exactly it, just sidestepping an intuitive race with dhcpd writing.  Somewhat hypothetical why that would happen, e.g. clustered updates for multiple NICs or whatever similar non-atomicity,  but it was easy to express that way,  put the update logic in one place (including the initial one at startup), and made the event timestamps sequences a little easier to follow when it wasn't clear why the updates were getting lost at all.  I thought the boolean variables helped document the admittedly simple logic too.   But none of that is critical.

Okay. Thank you for the explanation.

I will take this into account, but I will add some more changes, since we are performing a reload every time something changes which is causing a lot of load on busy systems.

Reloading this all multiple times a second isn’t a good idea. We should rather reload and then wait at least 5 seconds and then reload again if we had another inotify event.

This is probably slightly unrelated with your patch, but since we are already on it, I would like to have those changes implemented now.

I will get back to the list with those changes and submit them for review.

Best,
-Michael

> 
> A
> 
> On Mon, Mar 28, 2022, at 1:00 PM, Michael Tremer wrote:
>> Hello Anthony,
>> 
>> Thank you very much for submitting this patch and welcome to the list.
>> 
>> I understand that it is easier to track any changes in the directory, 
>> but I don’t quite understand why the logic had to be changed that the 
>> changes will be applied at the end only.
>> 
>> Is this just to avoid that multiple updates happen one after the other 
>> or what are you trying to achieve?
>> 
>> -Michael
>> 
>>> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>> 
>>> Switch from inotify watching individual files to monitoring the
>>> containing directories, as because dhcpd renames its leases file into a
>>> backup, monitoring the single inode does not work well.  Additionally,
>>> python appears to have a bug with replacing expired inotify watches on
>>> single files.
>>> ---
>>> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
>>> 1 file changed, 31 insertions(+), 16 deletions(-)
>>> 
>>> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
>>> index a2df5f1..6e22066 100644
>>> --- unbound-dhcp-leases-bridge
>>> +++ unbound-dhcp-leases-bridge
>>> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
>>> 		self.fix_leases_file = fix_leases_file
>>> 		self.hosts_file = hosts_file
>>> 
>>> +		# base mask for a completed file change
>>> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
>>> +		# IN_MODIFY since dhcpd appends lease updates to an open file
>>> +		self.watches = {
>>> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
>>> +		    self.fix_leases_file: mask,
>>> +		    self.hosts_file: mask
>>> +		}
>>> +
>>> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
>>> 		self.running = False
>>> 
>>> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
>>> 		self.running = True
>>> 
>>> 		# Initial setup
>>> -		self.hosts = self.read_static_hosts()
>>> -		self.update_dhcp_leases()
>>> +		update_hosts = True
>>> +		update_leases = True
>>> +
>>> +		i = inotify.adapters.Inotify()
>>> 
>>> -		i = inotify.adapters.Inotify([
>>> -			self.leases_file,
>>> -			self.fix_leases_file,
>>> -			self.hosts_file,
>>> -		])
>>> +		for f in self.watches:
>>> +			i.add_watch(os.path.dirname(f), self.watches[f])
>>> 
>>> 		for event in i.event_gen():
>>> 			# End if we are requested to terminate
>>> 			if not self.running:
>>> 				break
>>> 
>>> +			# Make pending updates once inotify queue is empty
>>> 			if event is None:
>>> +				if update_hosts:
>>> +					self.hosts = self.read_static_hosts()
>>> +					update_hosts = False
>>> +				if update_leases:
>>> +					self.update_dhcp_leases()
>>> +					update_leases = False
>>> 				continue
>>> 
>>> 			header, type_names, watch_path, filename = event
>>> 
>>> -			# Update leases after leases file has been modified
>>> -			if "IN_MODIFY" in type_names:
>>> -				# Reload hosts
>>> -				if watch_path == self.hosts_file:
>>> -					self.hosts = self.read_static_hosts()
>>> +			file = os.path.join(watch_path, filename)
>>> +
>>> +			if not file in self.watches:
>>> +				continue
>>> +
>>> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
>>> 
>>> -				self.update_dhcp_leases()
>>> +			update_leases = True
>>> 
>>> -			# If the file is deleted, we re-add the watcher
>>> -			if "IN_IGNORED" in type_names:
>>> -				i.add_watch(watch_path)
>>> +			if file == self.hosts_file:
>>> +				update_hosts = True
>>> 
>>> 		log.info("Unbound DHCP Leases Bridge terminated")
>>> 
>>> -- 
>>> 2.34.1
>>> 

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Michael Tremer]

[-- Attachment #1: Type: text/plain, Size: 5422 bytes --]

Please see the patch set that I just posted which is strongly based on your patches, but incorporates a couple of new changes, too.

Let me know if this looks good to you.

Best,
-Michael

> On 29 Mar 2022, at 10:39, Michael Tremer <michael.tremer(a)ipfire.org> wrote:
> 
> Hello,
> 
>> On 28 Mar 2022, at 20:55, Anthony Heading <ajrh(a)ajrh.net> wrote:
>> 
>> Hello Michael,
>> 
>> That was exactly it, just sidestepping an intuitive race with dhcpd writing.  Somewhat hypothetical why that would happen, e.g. clustered updates for multiple NICs or whatever similar non-atomicity,  but it was easy to express that way,  put the update logic in one place (including the initial one at startup), and made the event timestamps sequences a little easier to follow when it wasn't clear why the updates were getting lost at all.  I thought the boolean variables helped document the admittedly simple logic too.   But none of that is critical.
> 
> Okay. Thank you for the explanation.
> 
> I will take this into account, but I will add some more changes, since we are performing a reload every time something changes which is causing a lot of load on busy systems.
> 
> Reloading this all multiple times a second isn’t a good idea. We should rather reload and then wait at least 5 seconds and then reload again if we had another inotify event.
> 
> This is probably slightly unrelated with your patch, but since we are already on it, I would like to have those changes implemented now.
> 
> I will get back to the list with those changes and submit them for review.
> 
> Best,
> -Michael
> 
>> 
>> A
>> 
>> On Mon, Mar 28, 2022, at 1:00 PM, Michael Tremer wrote:
>>> Hello Anthony,
>>> 
>>> Thank you very much for submitting this patch and welcome to the list.
>>> 
>>> I understand that it is easier to track any changes in the directory, 
>>> but I don’t quite understand why the logic had to be changed that the 
>>> changes will be applied at the end only.
>>> 
>>> Is this just to avoid that multiple updates happen one after the other 
>>> or what are you trying to achieve?
>>> 
>>> -Michael
>>> 
>>>> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>>> 
>>>> Switch from inotify watching individual files to monitoring the
>>>> containing directories, as because dhcpd renames its leases file into a
>>>> backup, monitoring the single inode does not work well.  Additionally,
>>>> python appears to have a bug with replacing expired inotify watches on
>>>> single files.
>>>> ---
>>>> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
>>>> 1 file changed, 31 insertions(+), 16 deletions(-)
>>>> 
>>>> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
>>>> index a2df5f1..6e22066 100644
>>>> --- unbound-dhcp-leases-bridge
>>>> +++ unbound-dhcp-leases-bridge
>>>> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
>>>> 		self.fix_leases_file = fix_leases_file
>>>> 		self.hosts_file = hosts_file
>>>> 
>>>> +		# base mask for a completed file change
>>>> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
>>>> +		# IN_MODIFY since dhcpd appends lease updates to an open file
>>>> +		self.watches = {
>>>> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
>>>> +		    self.fix_leases_file: mask,
>>>> +		    self.hosts_file: mask
>>>> +		}
>>>> +
>>>> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
>>>> 		self.running = False
>>>> 
>>>> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
>>>> 		self.running = True
>>>> 
>>>> 		# Initial setup
>>>> -		self.hosts = self.read_static_hosts()
>>>> -		self.update_dhcp_leases()
>>>> +		update_hosts = True
>>>> +		update_leases = True
>>>> +
>>>> +		i = inotify.adapters.Inotify()
>>>> 
>>>> -		i = inotify.adapters.Inotify([
>>>> -			self.leases_file,
>>>> -			self.fix_leases_file,
>>>> -			self.hosts_file,
>>>> -		])
>>>> +		for f in self.watches:
>>>> +			i.add_watch(os.path.dirname(f), self.watches[f])
>>>> 
>>>> 		for event in i.event_gen():
>>>> 			# End if we are requested to terminate
>>>> 			if not self.running:
>>>> 				break
>>>> 
>>>> +			# Make pending updates once inotify queue is empty
>>>> 			if event is None:
>>>> +				if update_hosts:
>>>> +					self.hosts = self.read_static_hosts()
>>>> +					update_hosts = False
>>>> +				if update_leases:
>>>> +					self.update_dhcp_leases()
>>>> +					update_leases = False
>>>> 				continue
>>>> 
>>>> 			header, type_names, watch_path, filename = event
>>>> 
>>>> -			# Update leases after leases file has been modified
>>>> -			if "IN_MODIFY" in type_names:
>>>> -				# Reload hosts
>>>> -				if watch_path == self.hosts_file:
>>>> -					self.hosts = self.read_static_hosts()
>>>> +			file = os.path.join(watch_path, filename)
>>>> +
>>>> +			if not file in self.watches:
>>>> +				continue
>>>> +
>>>> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
>>>> 
>>>> -				self.update_dhcp_leases()
>>>> +			update_leases = True
>>>> 
>>>> -			# If the file is deleted, we re-add the watcher
>>>> -			if "IN_IGNORED" in type_names:
>>>> -				i.add_watch(watch_path)
>>>> +			if file == self.hosts_file:
>>>> +				update_hosts = True
>>>> 
>>>> 		log.info("Unbound DHCP Leases Bridge terminated")
>>>> 
>>>> -- 
>>>> 2.34.1
>>>> 
> 

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Anthony Heading]

[-- Attachment #1: Type: text/plain, Size: 6415 bytes --]

Michael,

Looks great to me.  Glad we're getting it fixed.  Only very minor comments:

1)  It looks like stderr is now left open even in daemon mode?  I doubt it's connected to anything that would block,  nor even that anything is actually written to stderr,  but not sure if you intended it.

2)  More generally, the bridge is somewhat taciturn in comparison to both dhcpd and unbound, I think a little more logging by default would be helpful for users looking at the syslog logs.  Either adding a single '-v' to the init.d script, or perhaps you might want to rebalance it differently,  but logging the DNS changes that are being made would be very useful I think,  and that would not be heavy when compared to what dhcpd is already generating in syslog.

Regards

Anthony
 
On Tue, Mar 29, 2022, at 7:35 AM, Michael Tremer wrote:
> Please see the patch set that I just posted which is strongly based on 
> your patches, but incorporates a couple of new changes, too.
>
> Let me know if this looks good to you.
>
> Best,
> -Michael
>
>> On 29 Mar 2022, at 10:39, Michael Tremer <michael.tremer(a)ipfire.org> wrote:
>> 
>> Hello,
>> 
>>> On 28 Mar 2022, at 20:55, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>> 
>>> Hello Michael,
>>> 
>>> That was exactly it, just sidestepping an intuitive race with dhcpd writing.  Somewhat hypothetical why that would happen, e.g. clustered updates for multiple NICs or whatever similar non-atomicity,  but it was easy to express that way,  put the update logic in one place (including the initial one at startup), and made the event timestamps sequences a little easier to follow when it wasn't clear why the updates were getting lost at all.  I thought the boolean variables helped document the admittedly simple logic too.   But none of that is critical.
>> 
>> Okay. Thank you for the explanation.
>> 
>> I will take this into account, but I will add some more changes, since we are performing a reload every time something changes which is causing a lot of load on busy systems.
>> 
>> Reloading this all multiple times a second isn’t a good idea. We should rather reload and then wait at least 5 seconds and then reload again if we had another inotify event.
>> 
>> This is probably slightly unrelated with your patch, but since we are already on it, I would like to have those changes implemented now.
>> 
>> I will get back to the list with those changes and submit them for review.
>> 
>> Best,
>> -Michael
>> 
>>> 
>>> A
>>> 
>>> On Mon, Mar 28, 2022, at 1:00 PM, Michael Tremer wrote:
>>>> Hello Anthony,
>>>> 
>>>> Thank you very much for submitting this patch and welcome to the list.
>>>> 
>>>> I understand that it is easier to track any changes in the directory, 
>>>> but I don’t quite understand why the logic had to be changed that the 
>>>> changes will be applied at the end only.
>>>> 
>>>> Is this just to avoid that multiple updates happen one after the other 
>>>> or what are you trying to achieve?
>>>> 
>>>> -Michael
>>>> 
>>>>> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>>>> 
>>>>> Switch from inotify watching individual files to monitoring the
>>>>> containing directories, as because dhcpd renames its leases file into a
>>>>> backup, monitoring the single inode does not work well.  Additionally,
>>>>> python appears to have a bug with replacing expired inotify watches on
>>>>> single files.
>>>>> ---
>>>>> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
>>>>> 1 file changed, 31 insertions(+), 16 deletions(-)
>>>>> 
>>>>> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
>>>>> index a2df5f1..6e22066 100644
>>>>> --- unbound-dhcp-leases-bridge
>>>>> +++ unbound-dhcp-leases-bridge
>>>>> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
>>>>> 		self.fix_leases_file = fix_leases_file
>>>>> 		self.hosts_file = hosts_file
>>>>> 
>>>>> +		# base mask for a completed file change
>>>>> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
>>>>> +		# IN_MODIFY since dhcpd appends lease updates to an open file
>>>>> +		self.watches = {
>>>>> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
>>>>> +		    self.fix_leases_file: mask,
>>>>> +		    self.hosts_file: mask
>>>>> +		}
>>>>> +
>>>>> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
>>>>> 		self.running = False
>>>>> 
>>>>> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
>>>>> 		self.running = True
>>>>> 
>>>>> 		# Initial setup
>>>>> -		self.hosts = self.read_static_hosts()
>>>>> -		self.update_dhcp_leases()
>>>>> +		update_hosts = True
>>>>> +		update_leases = True
>>>>> +
>>>>> +		i = inotify.adapters.Inotify()
>>>>> 
>>>>> -		i = inotify.adapters.Inotify([
>>>>> -			self.leases_file,
>>>>> -			self.fix_leases_file,
>>>>> -			self.hosts_file,
>>>>> -		])
>>>>> +		for f in self.watches:
>>>>> +			i.add_watch(os.path.dirname(f), self.watches[f])
>>>>> 
>>>>> 		for event in i.event_gen():
>>>>> 			# End if we are requested to terminate
>>>>> 			if not self.running:
>>>>> 				break
>>>>> 
>>>>> +			# Make pending updates once inotify queue is empty
>>>>> 			if event is None:
>>>>> +				if update_hosts:
>>>>> +					self.hosts = self.read_static_hosts()
>>>>> +					update_hosts = False
>>>>> +				if update_leases:
>>>>> +					self.update_dhcp_leases()
>>>>> +					update_leases = False
>>>>> 				continue
>>>>> 
>>>>> 			header, type_names, watch_path, filename = event
>>>>> 
>>>>> -			# Update leases after leases file has been modified
>>>>> -			if "IN_MODIFY" in type_names:
>>>>> -				# Reload hosts
>>>>> -				if watch_path == self.hosts_file:
>>>>> -					self.hosts = self.read_static_hosts()
>>>>> +			file = os.path.join(watch_path, filename)
>>>>> +
>>>>> +			if not file in self.watches:
>>>>> +				continue
>>>>> +
>>>>> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
>>>>> 
>>>>> -				self.update_dhcp_leases()
>>>>> +			update_leases = True
>>>>> 
>>>>> -			# If the file is deleted, we re-add the watcher
>>>>> -			if "IN_IGNORED" in type_names:
>>>>> -				i.add_watch(watch_path)
>>>>> +			if file == self.hosts_file:
>>>>> +				update_hosts = True
>>>>> 
>>>>> 		log.info("Unbound DHCP Leases Bridge terminated")
>>>>> 
>>>>> -- 
>>>>> 2.34.1
>>>>> 
>>

Re: [PATCH 1/3] unbound-dhcp-leases-bridge : fix bug 12694 - DHCP hosts not reliably propagated to DNS

[Michael Tremer]

[-- Attachment #1: Type: text/plain, Size: 7717 bytes --]

Hello,

> On 30 Mar 2022, at 04:30, Anthony Heading <ajrh(a)ajrh.net> wrote:
> 
> Michael,
> 
> Looks great to me.  Glad we're getting it fixed.  Only very minor comments:
> 
> 1)  It looks like stderr is now left open even in daemon mode?  I doubt it's connected to anything that would block,  nor even that anything is actually written to stderr,  but not sure if you intended it.

Yeah, I couldn’t merge your patch straight away and so I carried over the change manually. Since I am not entirely sure what all the daemon stuff is doing there, I thought that it would be enough to do what I did.

I will look into it again and fix this. Thank you for pointing this out.

> 2)  More generally, the bridge is somewhat taciturn in comparison to both dhcpd and unbound, I think a little more logging by default would be helpful for users looking at the syslog logs.  Either adding a single '-v' to the init.d script, or perhaps you might want to rebalance it differently,  but logging the DNS changes that are being made would be very useful I think,  and that would not be heavy when compared to what dhcpd is already generating in syslog.

Getting logging right is one of the hardest thing in software development I think. There is normally way too much logging or way too little. Balancing it exactly right is quite impossible for the developer, because they think about the program differently. I probably care about different things when writing software than a user.

I suppose changing the default log level doesn’t hurt anyone, and I suppose logging what you said into the syslog isn’t a bad idea. But is it needed during regular operation? No, because it should just work. We don’t want to clutter the logs with unnecessary stuff (there is already way too much in there that makes it impossible to follow it). I will have a look as well what I can change.

Best,
-Michael 

> Regards
> 
> Anthony
> 
> On Tue, Mar 29, 2022, at 7:35 AM, Michael Tremer wrote:
>> Please see the patch set that I just posted which is strongly based on 
>> your patches, but incorporates a couple of new changes, too.
>> 
>> Let me know if this looks good to you.
>> 
>> Best,
>> -Michael
>> 
>>> On 29 Mar 2022, at 10:39, Michael Tremer <michael.tremer(a)ipfire.org> wrote:
>>> 
>>> Hello,
>>> 
>>>> On 28 Mar 2022, at 20:55, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>>> 
>>>> Hello Michael,
>>>> 
>>>> That was exactly it, just sidestepping an intuitive race with dhcpd writing.  Somewhat hypothetical why that would happen, e.g. clustered updates for multiple NICs or whatever similar non-atomicity,  but it was easy to express that way,  put the update logic in one place (including the initial one at startup), and made the event timestamps sequences a little easier to follow when it wasn't clear why the updates were getting lost at all.  I thought the boolean variables helped document the admittedly simple logic too.   But none of that is critical.
>>> 
>>> Okay. Thank you for the explanation.
>>> 
>>> I will take this into account, but I will add some more changes, since we are performing a reload every time something changes which is causing a lot of load on busy systems.
>>> 
>>> Reloading this all multiple times a second isn’t a good idea. We should rather reload and then wait at least 5 seconds and then reload again if we had another inotify event.
>>> 
>>> This is probably slightly unrelated with your patch, but since we are already on it, I would like to have those changes implemented now.
>>> 
>>> I will get back to the list with those changes and submit them for review.
>>> 
>>> Best,
>>> -Michael
>>> 
>>>> 
>>>> A
>>>> 
>>>> On Mon, Mar 28, 2022, at 1:00 PM, Michael Tremer wrote:
>>>>> Hello Anthony,
>>>>> 
>>>>> Thank you very much for submitting this patch and welcome to the list.
>>>>> 
>>>>> I understand that it is easier to track any changes in the directory, 
>>>>> but I don’t quite understand why the logic had to be changed that the 
>>>>> changes will be applied at the end only.
>>>>> 
>>>>> Is this just to avoid that multiple updates happen one after the other 
>>>>> or what are you trying to achieve?
>>>>> 
>>>>> -Michael
>>>>> 
>>>>>> On 22 Mar 2022, at 03:47, Anthony Heading <ajrh(a)ajrh.net> wrote:
>>>>>> 
>>>>>> Switch from inotify watching individual files to monitoring the
>>>>>> containing directories, as because dhcpd renames its leases file into a
>>>>>> backup, monitoring the single inode does not work well.  Additionally,
>>>>>> python appears to have a bug with replacing expired inotify watches on
>>>>>> single files.
>>>>>> ---
>>>>>> unbound-dhcp-leases-bridge | 47 +++++++++++++++++++++++++-------------
>>>>>> 1 file changed, 31 insertions(+), 16 deletions(-)
>>>>>> 
>>>>>> diff --git unbound-dhcp-leases-bridge unbound-dhcp-leases-bridge
>>>>>> index a2df5f1..6e22066 100644
>>>>>> --- unbound-dhcp-leases-bridge
>>>>>> +++ unbound-dhcp-leases-bridge
>>>>>> @@ -72,6 +72,15 @@ class UnboundDHCPLeasesBridge(object):
>>>>>> 		self.fix_leases_file = fix_leases_file
>>>>>> 		self.hosts_file = hosts_file
>>>>>> 
>>>>>> +		# base mask for a completed file change
>>>>>> +		mask = inotify.constants.IN_CLOSE_WRITE | inotify.constants.IN_MOVED_TO
>>>>>> +		# IN_MODIFY since dhcpd appends lease updates to an open file
>>>>>> +		self.watches = {
>>>>>> +		    self.leases_file: mask | inotify.constants.IN_MODIFY,
>>>>>> +		    self.fix_leases_file: mask,
>>>>>> +		    self.hosts_file: mask
>>>>>> +		}
>>>>>> +
>>>>>> 		self.unbound = UnboundConfigWriter(unbound_leases_file)
>>>>>> 		self.running = False
>>>>>> 
>>>>>> @@ -80,36 +89,42 @@ class UnboundDHCPLeasesBridge(object):
>>>>>> 		self.running = True
>>>>>> 
>>>>>> 		# Initial setup
>>>>>> -		self.hosts = self.read_static_hosts()
>>>>>> -		self.update_dhcp_leases()
>>>>>> +		update_hosts = True
>>>>>> +		update_leases = True
>>>>>> +
>>>>>> +		i = inotify.adapters.Inotify()
>>>>>> 
>>>>>> -		i = inotify.adapters.Inotify([
>>>>>> -			self.leases_file,
>>>>>> -			self.fix_leases_file,
>>>>>> -			self.hosts_file,
>>>>>> -		])
>>>>>> +		for f in self.watches:
>>>>>> +			i.add_watch(os.path.dirname(f), self.watches[f])
>>>>>> 
>>>>>> 		for event in i.event_gen():
>>>>>> 			# End if we are requested to terminate
>>>>>> 			if not self.running:
>>>>>> 				break
>>>>>> 
>>>>>> +			# Make pending updates once inotify queue is empty
>>>>>> 			if event is None:
>>>>>> +				if update_hosts:
>>>>>> +					self.hosts = self.read_static_hosts()
>>>>>> +					update_hosts = False
>>>>>> +				if update_leases:
>>>>>> +					self.update_dhcp_leases()
>>>>>> +					update_leases = False
>>>>>> 				continue
>>>>>> 
>>>>>> 			header, type_names, watch_path, filename = event
>>>>>> 
>>>>>> -			# Update leases after leases file has been modified
>>>>>> -			if "IN_MODIFY" in type_names:
>>>>>> -				# Reload hosts
>>>>>> -				if watch_path == self.hosts_file:
>>>>>> -					self.hosts = self.read_static_hosts()
>>>>>> +			file = os.path.join(watch_path, filename)
>>>>>> +
>>>>>> +			if not file in self.watches:
>>>>>> +				continue
>>>>>> +
>>>>>> +			log.debug("Inotify %s: %s", file, " ".join(type_names))
>>>>>> 
>>>>>> -				self.update_dhcp_leases()
>>>>>> +			update_leases = True
>>>>>> 
>>>>>> -			# If the file is deleted, we re-add the watcher
>>>>>> -			if "IN_IGNORED" in type_names:
>>>>>> -				i.add_watch(watch_path)
>>>>>> +			if file == self.hosts_file:
>>>>>> +				update_hosts = True
>>>>>> 
>>>>>> 		log.info("Unbound DHCP Leases Bridge terminated")
>>>>>> 
>>>>>> -- 
>>>>>> 2.34.1
>>>>>> 
>>>