dhcp process errors in log

louis2 · Jun 12, 2020, 12:06 PM

Hello,

I notice the folling errors in the log

Jun 12 13:50:44 pfSense dhcpleases[88140]: kqueue error: unknown
Jun 12 13:50:44 pfSense dhcpleases[88140]: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Jun 12 13:50:44 pfSense dhcpleases[49211]: /etc/hosts changed size from original!
Jun 12 13:50:36 pfSense check_reload_status[637]: Syncing firewall
Jun 12 13:49:33 pfSense dhcpleases[49211]: kqueue error: unknown
Jun 12 13:49:33 pfSense dhcpleases[49211]: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Jun 12 13:49:33 pfSense dhcpleases[68124]: /etc/hosts changed size from original!

Especially, the "kqueue error" and the "pidfile (/var/run/unbound.pid) does not exist" seems NOT-OK to me.

Sincerely,

Louis

rpsmith · Jun 12, 2020, 8:02 PM

@louis2 said in dhcp process errors in log:

kqueue

Same "kqueue error: unknown" here on Fri Jun 12 07:05:10 EDT 2020 build.

Gertjan · Jun 13, 2020, 9:16 AM

Hi,

The DHCP server(s) on your LAN(s) serve DHCP requests.
A request comes in, the DHCP server proposes an IP.
Normally, the lease period will last a couple of hours, but this value can be changed - a default value can be set in the DHCP server, something like 12 hours, or even set extremly low. The DJCP client can even decide not to sue this proposal, and use, for example, a very low duration like 10 seconds.
What happens is : the device will ask a new IP (and gateway, DNS, etc) every 10 seconds.
This is totally unneeded, but thus far with not much consequences.

But :
If this one is set / checked :
login-to-view

then, with every new lease request, the resolver is restarted.

Check the resolver log : is this he case.

Or, goto console / SSH, option 8 and execute :

clog /var/log/resolver.log | grep 'Restart'

Your log messages :
dhcpleases is the process that restarts unbound when a new lease comes in.
It tries to restart unbound, but it was already "off line" (the pid file wasn't there) - during a restart phase.

Normally, unbound, restarts in a couple of seconds.
Lately, people went nuts with pfBlockerNG-devel, added millions of DNSBL and are surprised that the resolver needs minutes (!!) to restart (like : I overload the plan and I'm surprised it doesn't take off ....... how come ??).

This :

/etc/hosts changed size from original!

is shown when an instance of of dhcpleases is reading the hosts file, adding a entry like

2001:470:1f13:5c0:2::cc EPACKFERPAR22.brit-hotel-fumel.net EPACKFERPAR22

and writing it back.
At that moment, another instance of dhcpleases was doing the same thing => conflict !

I bet your system is getting hit hard with some stupid device that chain gun's pfSense with DHCP requests.
To check : see the DHCP server log. Is there a such device ?

Also : think it over : and remove the check for
DHCP Registration => Register DHCP leases in the DNS Resolver
(see image above).

louis2 · Jun 13, 2020, 1:15 PM

Hello,

DHCP registration (IPV4) for both static and leases was turned on. I turned the one for leases off.

But on the other hand the number of queries coming in is not really exceptional. Every couple of seconds I see a request e.g. from my Lan-printer (every 30 seconds).

Also note that the same happens perhaps even a bit more frequent from IPV6-sources (registration was off there).

I must think a bit longer about if it is yes or no a good idea to do the registration.

One of the issues I have, since SMB1 is disabled, is that e.g. SMB does function, but you can not see the share in another LAN. I think a historic design problem, but DNS does play a role in solving that issue.

What I can say is that it is IMHO ridiculous to restart the dhcp server, just to reload the config !

Related to domains, I use the following principal:

overal domain is "lan" (no dot I hope that is correct)
per vlan there is defined a separate sub-domain like "pc.lan" , "iot.lan"
Hope that that is correct.

Sincerely,

Louis

Gertjan · Jun 13, 2020, 1:15 PM

@louis2 said in dhcp process errors in log:

. Every couple of seconds I see a request e.g. from my Lan-printer (every 30 seconds).

@louis2 said in dhcp process errors in log:

not really exceptional

Not ????
It's plain broken - needs to be investigated.

@louis2 said in dhcp process errors in log:

I must think a bit longer about if it is yes or no a good idea to do the registration.

Noop. The thinking part is done.
Having 'restart' unbound every 30 seconds - give or take it 15 seconds start tile, that means half of the time your have no DNS system running.
DNS caching doesn't work, the cache is thrown away every 30 seconds.
No good at all.
Have a talk with this printer. And if the discussion doesn't work out, give it a fixed IPv4.

@louis2 said in dhcp process errors in log:

IMHO ridiculous to restart the dhcp server,

The dhcp server isn't restarting.
It's unbound, the Resolver, because one of the config files that he reads at start time is changed (a new device was registered to the network).
This subject is known for year - see my other (a couple of hundreds or so the last 4 years ?) 'unbound' versus DHCP Registration threads.
And no, pfSense doesn't write neither maintain unbound.

louis2 · Jun 13, 2020, 1:15 PM

Gertjan,

I also tried SSH option 8
clog /var/log/resolver.log | grep 'Restart'

result (running 2.5 dev) is "command not found",
but from the normal log (I copied a piece below), lot of IPV6 but nothing really extreme, I think.

For info I have 9 VLAN's, all very very small, sometime only having one device at the moment, having DHCP enabled for IPV4 and IPV6.

Louis

Gertjan · Jun 13, 2020, 1:18 PM

@louis2 said in dhcp process errors in log:

(running 2.5 dev)

2.5.0 users (the exeprts !!) should know that 2.5.0 ditched clog - the log are 'plain text' now, no more rotating logs (clog).

So, what about a

cat /var/log/resolver.log | grep 'Restart'

I'm no expert, so I stay away from 2.5.0 ;)

louis2 · Jun 13, 2020, 1:20 PM

Strange thing is that this HP-printer gets a static IP from the DHCP-server IPV4 and IPV6.

Louis
PS I was writing a mail with a part of the log as example, but the bloudy website did block it as spam.

Louis

Gertjan · Jun 13, 2020, 1:24 PM

@louis2 said in dhcp process errors in log:

HP-printer gets a static IP from the DHCP-server IPV4 and IPV6.

You mean you've set a "DHCP Static Mappings" or MAC based Lease for it ?

Set these on the DHCP server :

login-to-view

Or abandon DHCP usage for that printer : set it static : this has to be done "on the printer", not pfSense.

louis2 · Jun 13, 2020, 1:28 PM

@Gertjan said in dhcp process errors in log:

cat /var/log/resolver.log | grep 'Restart'

the result is "zero" :)

default lease time (IPV6 only the printer) is 300 I see. I probably did that for testing, have change that bakc to the default two hours.

IPV4 was unchanged (default 7200 seconds)

Louis

louis2 · Jun 13, 2020, 3:41 PM

Gertjan,

I did:

disable Register DHCP leases in the DNS Resolver
enabled Register DHCP static mappings in the DNS Resolver (did not change that)
DHCP V4 and V6 set lease times 7200 s every where (default)
Reboot

The log (one try only) did not show any of the following messages:

Jun 12 13:50:44 pfSense dhcpleases[88140]: kqueue error: unknown
Jun 12 13:50:44 pfSense dhcpleases[88140]: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process.
Jun 12 13:50:44 pfSense dhcpleases[49211]: /etc/hosts changed size from original!

cat /var/log/resolver.log | grep 'Restart' does not return any rows, just like before!

I do the static mapping normally from the DHCP-server, since I prefer a centralized management and IP-overview

As you already wrote:
Having 'restart' unbound every 30 seconds - give or take it 15 seconds start tile, that means half of the time your have no DNS system running.
DNS caching doesn't work, the cache is thrown away every 30 seconds.
No good at all. However that ubound behavoir is IMHO not good at all !!!

So to a certain extent we fixed this issue, however it is better to say that we mitigated it. It is not fixed nor OK.

Another remark you made "Having 'restart' unbound every 30 seconds - give or take it 15 seconds start tile, that means half of the time your have no DNS system running." Do make me thing about an issue I noted since two days, beeing service interruptions on Tidal (streaming service) and YouTube. I wonder if those issues where perhaps related to this DNS-issue ......

I will pay extra attention to that in the comming days.

Thanks for the mails,

Louis

louis2 · Jun 13, 2020, 7:05 PM

@Gertjan said in dhcp process errors in log:

Having 'restart' unbound every 30 seconds

........ I do not know how unbound is exactly working nor how it is doing its job together with the dhcp server, however ...

I noticed that 2.5 develpment is running the very latest unbound version (1.10.1)
I also had a look at the unbound website "https://nlnetlabs.nl/documentation/unbound/unbound-control/"

under COMMANDS one of the commands is "reload" ...... so I do not understand the restarts needed at every change in the "host_entries.conf" as described in the discussion above ....

of course I admit that the errors are gone (I hope), but I do not understand what happens ...

Louis

Gertjan · Jun 15, 2020, 6:53 AM

@louis2 said in dhcp process errors in log:

under COMMANDS one of the commands is "reload" ...... so I do not understand the restarts needed at every change in the "host_entries.conf" as described in the discussion above ....

Unbound is open source.
Have a look, at what the control command "reload" does when the unbound process receives it.
It stops itself. And starts itself.
"It's in the code" ;)

@louis2 said in dhcp process errors in log:

........ I do not know how unbound is exactly working nor how it is doing its job together with the dhcp serve

It's a resolver.
A global wike.org page will detail that.

I tend to think :
Everything that is local can not be requested elsewhere, because how would the Internet know how to resolve "yourpc.yourlocaldomain" ?
So unbound knows that .yourlocaldomain is your local domain.
Everything else is known locally and resolved is used.
Use :

dig microsoft.com +trace

to see this work.

About the DHCP server :
It maintains a pool of IP address, and hand one over to a device if it asks one. When the device is doing so, it hands over a "host name" to the DHCP server. The DHCP server will put this name into it leases file /var/dhcpd/var/db/dhcpd.leases

If you just connected a file server to your network, with a host name like "fileserver" then the leases file will contain :

lease 192.168.1.115 {
  starts 1 2020/06/15 01:19:21;
  ends 2 2020/06/16 01:19:21;
  cltt 1 2020/06/15 01:19:21;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 30:3a:bb:8d:e6:69;
  uid "\0010:d\215\356c";
  set vendor-class-identifier = "MSFT 5.0";
  client-hostname "fileserver";
}

but if you want to use on another device (PC) something like this :

\\fileserver

or

\\fileserver.yourlocaldoman

then you wouldn't be able to fnd it.

unbound doesn't know what 'dhcpd' is, neither ca,, it read it's (internal) leases file.

That's where the process "dhcpleases" kicks in.
This process is created when you activate (check) :

login-to-view

It's a separate process, that reads the dhcpd leases files, finds new ones, and writes them to the /var/unbound/dhcpleases_entries.conf file, where unbound can find it.

unbound is not capable of detecting a change of that (any) configuration file during executing. It reads them only when it starts, as it is part of its configuration. Change that (any) configuration file could be seen as a configuration change. So : restart.

It's the choice of (pfSense) application that introduces a possible issue = very frequent unbound restarts. A redmine report was created years ago.
Possible solutions are : re write the resolver, or choose a resolver that handles this situation, like 'bind'.
Note : the file and memory footprint, compared to Unbound, is several ten times bigger ...

Ones the 'unbound' restarting issue is recognized and known, it can be solved easily.
We, as firewall router admins, have to to something to justify our jobs ^^
Some basic knowledge of DHCP and DNS are needed, though. Like a taxi driver should have a licence to drive ^^

louis2 · Jun 15, 2020, 7:23 AM

Thanks again Gertjan,

Glad that the issue is gone now ...

However I do only partly agree on your taxi driver, story. IMHO problems should be fixed where they are .....

Louis