DHCP issues

interessierter · Apr 12, 2020, 1:26 PM

Hello folks!

Yesterday my pfsense was not able to start up successfully. I have checked the console with a serial cable, and could see, that she was handing while starting the DNS resolver. However I have installed the latest version and recovered with a backup. I have still very strange problems:

Most of the time, when I have DHCP on my client selected, I simply do ned get a IP address. I can open the webinterface of the pfsense and I face the same problem with my mobile phone. After some time with unknow magic, it simply works and I get a DHCP address. After some time it s the opposit around.

Before I was in the believe of a heat problem, but I can reproduce it. ANY ideas what the issue is here? I m investigating the issue since yesterday. DHCP service is running, 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:15 dhcpd Server starting service.
Apr 12 15:17:15 dhcpd Sending on Socket/fallback/fallback-net
Apr 12 15:17:15 dhcpd Sending on BPF/re2/00:0d:b9:3c:ca:36/192.168.1.0/24
Apr 12 15:17:15 dhcpd Listening on BPF/re2/00:0d:b9:3c:ca:36/192.168.1.0/24
Apr 12 15:17:15 dhcpd Wrote 3 leases to leases file.
Apr 12 15:17:15 dhcpd Wrote 0 new dynamic host decls to leases file.
Apr 12 15:17:15 dhcpd Wrote 0 deleted host decls to leases file.
Apr 12 15:17:15 dhcpd For info, please visit https://www.isc.org/software/dhcp/
Apr 12 15:17:15 dhcpd All rights reserved.
Apr 12 15:17:15 dhcpd Copyright 2004-2018 Internet Systems Consortium.
Apr 12 15:17:15 dhcpd Internet Systems Consortium DHCP Server 4.4.1
Apr 12 15:17:15 dhcpd PID file: /var/run/dhcpd.pid
Apr 12 15:17:15 dhcpd Database file: /var/db/dhcpd.leases
Apr 12 15:17:15 dhcpd Config file: /etc/dhcpd.conf
Apr 12 15:17:15 dhcpd For info, please visit https://www.isc.org/software/dhcp/
Apr 12 15:17:15 dhcpd All rights reserved.
Apr 12 15:17:15 dhcpd Copyright 2004-2018 Internet Systems Consortium.
Apr 12 15:17:15 dhcpd Internet Systems Consortium DHCP Server 4.4.1
Apr 12 15:17:13 dhcpleases Sending HUP signal to dns daemon(76835)

interessierter · Apr 13, 2020, 7:53 AM

Found the issue yesterday.
The problem was, that DHCP snooping was enabled on the switch, that connects the pfsense

Gertjan · Apr 13, 2020, 9:05 AM

@interessierter said in DHCP issues:

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 · Apr 13, 2020, 9:09 AM

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 · Apr 29, 2020, 7:06 AM

Hello folks!

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

Gertjan · Apr 29, 2020, 3:16 PM

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 · Apr 29, 2020, 3:29 PM

more then one time a second.

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

interessierter · Apr 30, 2020, 8:36 AM

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 · Apr 30, 2020, 10:21 AM

@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, 2020, 10:23 AM

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 · Apr 30, 2020, 12:34 PM

@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 · May 1, 2020, 7:10 AM

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

Gertjan · May 1, 2020, 7:22 AM

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 · May 1, 2020, 7:26 AM

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 · May 1, 2020, 9:33 AM

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 · May 1, 2020, 9:38 AM

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 · May 1, 2020, 9:40 AM

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 · May 1, 2020, 9:42 AM

@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 · May 1, 2020, 9:43 AM

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 · May 2, 2020, 7:53 AM

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