DHCP issues

Gertjan

the log does not show something special:

Apr 12 15:17:15 dhcpleases Sending HUP signal to dns daemon(76835)
Apr 12 15:17:15 dhcpleases Sending HUP signal to dns daemon(76835)
.....
Apr 12 15:17:13 dhcpleases Sending HUP signal to dns daemon(76835)

That is, except for the fact dhcpleases is restarting the dns demaon (unbound) every 3 seconds .... (the rest of these log line are of zero interest)
And that was when NO DHCP leases were handed out.

And now it is working, and new leases are coming in, is it restarting even more often ??

interessierter

HUP signal means restart of the service.

No since the change of the switch yesterday, I don t see this error messages anymore. So no restarts

interessierter

Hello folks!

Since yesterday, the DNS Resolver restarting the loop. What can I do?

Gertjan

Is unbound restarting ? Often ?
(no need to paste the entire unbound/dns log file, just the lines where it says it started).

Like :

Apr 25 09:21:08 	unbound 	54443:0 	info: start of service (unbound 1.9.6).

A couple of lines lower (earlier that is) you'll find

Apr 25 09:21:00 	unbound 	10838:0 	info: service stopped (unbound 1.9.6).

Up to you to check the other logs to see what might be responsible for the "stop" event (at that very moment, or second or so before).

interessierter

more then one time a second.

Stop message is always the same: info: service stopped (unbound 1.9.6).

interessierter

Some weeks ago, I enabled DNS/TLS and created a Firewall rule to open the required port. Since I disabled the firewall rule, the DNS server now starts every 10 minutes.

is that normal?

Gertjan

@interessierter said in DHCP issues:

is that normal?

Well, no.
But yes, it's very possible to create a situation.

unbound by itself will never terminate,, except when it is instructed to do so.
Like : a new lDHCP lease comes in, or an interface to which is is attached goes down - or comes up. Etc etc.
All these event are logged.
So, again : what do the logs say ?

interessierter

Apr 30 12:19:28 unbound 86307:1 info: generate keytag query _ta-4f66. NULL IN
Apr 30 12:19:26 unbound 86307:0 info: start of service (unbound 1.9.6).
Apr 30 12:19:26 unbound 86307:0 notice: init module 1: iterator
Apr 30 12:19:26 unbound 86307:0 notice: init module 0: validator
Apr 30 12:19:26 unbound 86307:0 notice: Restart of unbound 1.9.6.
Apr 30 12:19:26 unbound 86307:0 info: 32.000000 64.000000 2
Apr 30 12:19:26 unbound 86307:0 info: 16.000000 32.000000 33
Apr 30 12:19:26 unbound 86307:0 info: 8.000000 16.000000 51
Apr 30 12:19:26 unbound 86307:0 info: 4.000000 8.000000 23
Apr 30 12:19:26 unbound 86307:0 info: 2.000000 4.000000 25
Apr 30 12:19:26 unbound 86307:0 info: 1.000000 2.000000 15
Apr 30 12:19:26 unbound 86307:0 info: 0.524288 1.000000 32
Apr 30 12:19:26 unbound 86307:0 info: 0.262144 0.524288 60
Apr 30 12:19:26 unbound 86307:0 info: 0.131072 0.262144 41
Apr 30 12:19:26 unbound 86307:0 info: 0.065536 0.131072 58
Apr 30 12:19:26 unbound 86307:0 info: 0.032768 0.065536 1
Apr 30 12:19:26 unbound 86307:0 info: 0.016384 0.032768 3
Apr 30 12:19:26 unbound 86307:0 info: 0.000000 0.000001 2
Apr 30 12:19:26 unbound 86307:0 info: lower(secs) upper(secs) recursions
Apr 30 12:19:26 unbound 86307:0 info: [25%]=0.203002 median[50%]=0.643216 [75%]=7.91304
Apr 30 12:19:26 unbound 86307:0 info: histogram of recursion processing times
Apr 30 12:19:26 unbound 86307:0 info: average recursion processing time 4.977961 sec
Apr 30 12:19:26 unbound 86307:0 info: server stats for thread 1: requestlist max 25 avg 6.51734 exceeded 0 jostled 0
Apr 30 12:19:26 unbound 86307:0 info: server stats for thread 1: 479 queries, 133 answers from cache, 346 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Apr 30 12:19:26 unbound 86307:0 info: 32.000000 64.000000 4
Apr 30 12:19:26 unbound 86307:0 info: 16.000000 32.000000 37
Apr 30 12:19:26 unbound 86307:0 info: 8.000000 16.000000 56
Apr 30 12:19:26 unbound 86307:0 info: 4.000000 8.000000 65
Apr 30 12:19:26 unbound 86307:0 info: 2.000000 4.000000 65
Apr 30 12:19:26 unbound 86307:0 info: 1.000000 2.000000 29
Apr 30 12:19:26 unbound 86307:0 info: 0.524288 1.000000 44
Apr 30 12:19:26 unbound 86307:0 info: 0.262144 0.524288 73
Apr 30 12:19:26 unbound 86307:0 info: 0.131072 0.262144 51
Apr 30 12:19:26 unbound 86307:0 info: 0.065536 0.131072 91
Apr 30 12:19:26 unbound 86307:0 info: 0.032768 0.065536 2
Apr 30 12:19:26 unbound 86307:0 info: 0.016384 0.032768 2
Apr 30 12:19:26 unbound 86307:0 info: 0.008192 0.016384 3
Apr 30 12:19:26 unbound 86307:0 info: 0.004096 0.008192 2
Apr 30 12:19:26 unbound 86307:0 info: 0.001024 0.002048 1
Apr 30 12:19:26 unbound 86307:0 info: 0.000000 0.000001 2
Apr 30 12:19:26 unbound 86307:0 info: lower(secs) upper(secs) recursions
Apr 30 12:19:26 unbound 86307:0 info: [25%]=0.204961 median[50%]=0.918913 [75%]=5.86154
Apr 30 12:19:26 unbound 86307:0 info: histogram of recursion processing times
Apr 30 12:19:26 unbound 86307:0 info: average recursion processing time 4.468584 sec
Apr 30 12:19:26 unbound 86307:0 info: server stats for thread 0: requestlist max 21 avg 6.57116 exceeded 0 jostled 0
Apr 30 12:19:26 unbound 86307:0 info: server stats for thread 0: 750 queries, 223 answers from cache, 527 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Apr 30 12:19:26 unbound 86307:0 info: service stopped (unbound 1.9.6).

Gertjan

@Gertjan said in DHCP issues:

(no need to paste the entire unbound/dns log file, just the lines where it says it started).

As said above, no need to post the info that is present between start and stop. We all have he same lines. It's part of the start-up process. Between stop and start there is nothing .... because unbound wasn't running.

@Gertjan said in DHCP issues:

So, again : what do the logs say ?

What I meant was this :

@Gertjan said in DHCP issues:

Up to you to check the other logs to see what might be responsible for the "stop" event (at that very moment, or second or so before).

So ... ???

interessierter

OK and in which log should I look? General?
Can not find something special.

Gertjan

Look for these :
@interessierter said in DHCP issues:

Apr 12 15:17:13 dhcpleases Sending HUP signal to dns daemon(76835)

which should be in the DHCP log ^^
The dhcpleases process is the one that can restart unbound if a new DHCP lease are registered.

It could also be an interface that goes up and down. See System log for that.

Can you list your services ?
Like :

Some of these could be candidates.

interessierter

DHCP Log is pretty boring:

May 1 09:23:30 dhcpd DHCPACK on 192.168.1.51 to 00:0a:b3:03:0b:72 (gira) via re2
May 1 09:23:30 dhcpd DHCPREQUEST for 192.168.1.51 (192.168.1.1) from 00:0a:b3:03:0b:72 (gira) via re2
May 1 09:23:30 dhcpd reuse_lease: lease age 572 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.51
May 1 09:23:30 dhcpd DHCPOFFER on 192.168.1.51 to 00:0a:b3:03:0b:72 (gira) via re2
May 1 09:23:29 dhcpd DHCPDISCOVER from 00:0a:b3:03:0b:72 (gira) via re2
May 1 09:23:29 dhcpd reuse_lease: lease age 571 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.1.51
May 1 09:19:28 dhcpleases Sending HUP signal to dns daemon(86307)
May 1 09:19:28 dhcpd DHCPACK on 192.168.1.53 to 68:9a:87:9a:bb:5f (amazon-07146cf52) via re2
May 1 09:19:28 dhcpd DHCPREQUEST for 192.168.1.53 from 68:9a:87:9a:bb:5f (amazon-07146cf52) via re2
May 1 09:13:58 dhcpleases Sending HUP signal to dns daemon(86307)
May 1 09:13:58 dhcpd DHCPACK on 192.168.1.51 to 00:0a:b3:03:0b:72 (gira) via re2

services:

Gertjan

This one restarts unbound :

@interessierter said in DHCP issues:

May 1 09:13:58 dhcpleases Sending HUP signal to dns daemon(86307)

are there more ? how often ?

Who is this :

The ancient one ?

These :
arpwatch - bandwithd - clamd - darkstat - radiusd - snort - squid

vnstard : don't know.
iperf : idem.

are, what I call, expert packages.
Solid knowledge of the (FreeBSD) file system and OS specific know hows. Otherwise, setting them up and be able to debug will be a huge no-go.
These are all packages that are designed to run without a GUI front end. The fact that pfSEnse offers a GUI front end does not mean they are easier to administer. On the contrary.

I advise you to stabilize your system first. That means : use what you get when you installed pfSense. Nothing more.

interessierter

Hi!

The system run now since years with this package and mostly the same configuration. Is use the DNSBL for getting IP lists and block if there is a request coming. When I disable the service, there is no change in the behavior, also when I disable pfBlocker

interessierter

PS: On the gui I have no option anymore to uninstall this services, they are not listed andmore in the installed packages view. That is since there was a need to recover the firewall and restore from backup

Gertjan

@interessierter said in DHCP issues:

no option anymore to uninstall this services

So the settings are rather 'non-defined'.
A good reason the re set it up - clean.

interessierter

No the installed software is simply not in the section of installed addin.

I have reinstalled and restores with a backup 3 weeks ago

interessierter

It seems like that every time the DHCP server is writing this one in the Log:

May 2 09:50:08 dhcpleases Sending HUP signal to dns daemon(86307)

The DNS Resolver restart

Gertjan

@interessierter said in DHCP issues:

It seems like that every time the DHCP server is writing this one in the Log:
May 2 09:50:08 dhcpleases Sending HUP signal to dns daemon(86307)
The DNS Resolver restart

That's normal.

THe question to be asked is : what is the reason that a device (more, devices ?) are asking every 3 seconds for a new lease ?

What is the lease time setup in pfSense => DHCP server ?
What is the lease time received by a (the) device(s) ? ( on a Windows PC, ise "ipconfig /all" and you see the lease start and end)

Also,
If this option is set (checked) :

Then yeah, you're asking that unbound, the Resolver, gets restarted when a new DHCP gets registered.

For this and more reasons, it is very advisable to declare all your known devices with a DHCP-static -leases on pfSense.
This way unbound doesn't get hammered any more if some stupid device is re asking a new lease every XX seconds.

Still, look for this device, and throw it out of the windows - out of the Wifi range if you have one.

interessierter

DHCP registration is checked as this makes sense why not?

And you are right, it seems like my dhcp lease is only 3 secs valid. But where is the option to change this? I have never touched this