DHCP Server keeps crashing

senseivita

Suddenly DHCP started crashing.

I noticed when this desk video phone started flickering and popping up messages of "DNS lookup failed", randomly (de)registering on and off. On my computer, Little Snitch show notifications of profile change, these are triggered when Little Snitch detects a L3 connection just came up (like a DHCP lease.)

In the DHCP log is hard to see anything other than a server that seems OK. Over SSH, I tried dmesg in SSH and just showed a lot of IPv6 nonsense which I had just deactivated to focus on one stack at a time. tail -f /var/log/dhcpd.log seemed OK too at first. Basically the GUI with the newest entry at the bottom except that about a minute later it started scrolling a lot, this is one loop:

[Line   1] Aug 18 04:02:01 routelogic dhcpd[46662]: Server starting service.
[Line   2] Aug 18 04:02:01 routelogic dhcpd[46662]: uid lease 10.7.0.153 for client 44:d9:e7:94:26:fb is duplicate on 10.7.0.0/24
[Line   3] Aug 18 04:02:01 routelogic dhcpd[46662]: DHCPDISCOVER from 44:d9:e7:94:26:fb via vmx0.7
[Line   4] Aug 18 04:02:01 routelogic dhcpd[46662]: DHCPOFFER on 10.7.0.41 to 44:d9:e7:94:26:fb via vmx0.7
[Line   5] Aug 18 04:02:01 routelogic dhcpd[46662]: uid lease 10.7.0.153 for client 44:d9:e7:94:26:fb is duplicate on 10.7.0.0/24
[Line   6] Aug 18 04:02:01 routelogic dhcpd[46662]: DHCPREQUEST for 10.7.0.41 (10.7.0.1) from 44:d9:e7:94:26:fb via vmx0.7
[Line  11] Aug 18 04:02:02 routelogic dhcpd[46662]: DHCPACK on 10.7.0.154 to 00:23:df:9d:5c:c0 (zx8) via vmx0.7
[Line  12] Aug 18 04:02:02 routelogic dhcpd[47762]: Internet Systems Consortium DHCP Server 4.4.2-P1
[Line  13] Aug 18 04:02:02 routelogic dhcpd[47762]: Copyright 2004-2021 Internet Systems Consortium.
[Line  14] Aug 18 04:02:02 routelogic dhcpd[47762]: All rights reserved.
[Line  15] Aug 18 04:02:02 routelogic dhcpd[47762]: For info, please visit https://www.isc.org/software/dhcp/
[Line  16] Aug 18 04:02:02 routelogic dhcpd[47762]: Config file: /etc/dhcpdv6.conf
[Line  17] Aug 18 04:02:02 routelogic dhcpd[47762]: Internet Systems Consortium DHCP Server 4.4.2-P1
[Line  18] Aug 18 04:02:02 routelogic dhcpd[47762]: Database file: /var/db/dhcpd6.leases
[Line  19] Aug 18 04:02:02 routelogic dhcpd[47762]: Copyright 2004-2021 Internet Systems Consortium.
[Line  20] Aug 18 04:02:02 routelogic dhcpd[47762]: PID file: /var/run/dhcpdv6.pid
[Line  21] Aug 18 04:02:02 routelogic dhcpd[47762]: All rights reserved.
[Line  22] Aug 18 04:02:02 routelogic dhcpd[47762]: For info, please visit https://www.isc.org/software/dhcp/
[Line  23] Aug 18 04:02:02 routelogic dhcpd[47762]: Wrote 0 deleted host decls to leases file.
[Line  24] Aug 18 04:02:02 routelogic dhcpd[47762]: Wrote 0 new dynamic host decls to leases file.
[Line  25] Aug 18 04:02:02 routelogic dhcpd[47762]: Wrote 16 NA, 0 TA, 0 PD leases to lease file.
[Line  26] Aug 18 04:02:02 routelogic dhcpd[47762]: Bound to *:547
[Line  27] Aug 18 04:02:02 routelogic dhcpd[47762]: Listening on Socket/7/vmx0.11/2001:470:b9dd:11::/64
[Line  28] Aug 18 04:02:02 routelogic dhcpd[47762]: Sending on   Socket/7/vmx0.11/2001:470:b9dd:11::/64
[Line  29] Aug 18 04:02:02 routelogic dhcpd[47762]: Listening on Socket/7/vmx0.7/2001:470:b9dd:7::/64
[Line  30] Aug 18 04:02:02 routelogic dhcpd[47762]: Sending on   Socket/7/vmx0.7/2001:470:b9dd:7::/64
[Line  31] Aug 18 04:02:02 routelogic dhcpd[47762]: Listening on Socket/7/vmx0.9/2001:470:b9dd:9::/64
[Line  32] Aug 18 04:02:02 routelogic dhcpd[47762]: Sending on   Socket/7/vmx0.9/2001:470:b9dd:9::/64
[Line  33] Aug 18 04:02:02 routelogic dhcpd[47762]: Listening on Socket/7/vmx0.6/2001:470:b9dd:6::/64
[Line  34] Aug 18 04:02:02 routelogic dhcpd[47762]: Sending on   Socket/7/vmx0.6/2001:470:b9dd:6::/64
[Line  35] Aug 18 04:02:02 routelogic dhcpd[47762]: Server starting service.
[Line  36] Aug 18 04:02:03 routelogic dhcpd[46662]: uid lease 10.9.0.201 for client 00:23:df:9d:5c:c0 is duplicate on 10.9.0.0/24
[Line  37] Aug 18 04:02:03 routelogic dhcpd[46662]: DHCPREQUEST for 10.9.0.18 from 00:23:df:9d:5c:c0 via vmx0.9
[Line  38] Aug 18 04:02:25 routelogic dhcpd[46662]: ntp.vitanetworks.link: temporary name server failure
[Line  39] Aug 18 04:02:47 routelogic dhcpd[46662]: zz.vitanetworks.link: temporary name server failure
[Line  40] Aug 18 04:02:47 routelogic dhcpd[46662]: DHCPACK on 10.9.0.18 to 00:23:df:9d:5c:c0 via vmx0.9
[Line 129] Aug 18 04:02:49 routelogic dhcpd[46662]: DHCPACK on 10.7.0.157 to 0c:4d:e9:cf:99:50 (zx6vitaorkslink) via vmx0.7
[Line 130] Aug 18 04:03:01 routelogic dhcpd[6528]: Internet Systems Consortium DHCP Server 4.4.2-P1
[Line 131] Aug 18 04:03:01 routelogic dhcpd[6528]: Copyright 2004-2021 Internet Systems Consortium.
[Line 132] Aug 18 04:03:01 routelogic dhcpd[6528]: All rights reserved.
[Line 133] Aug 18 04:03:01 routelogic dhcpd[6528]: For info, please visit https://www.isc.org/software/dhcp/
[Line 134] Aug 18 04:03:01 routelogic dhcpd[6528]: Config file: /etc/dhcpd.conf
[Line 135] Aug 18 04:03:01 routelogic dhcpd[6528]: Internet Systems Consortium DHCP Server 4.4.2-P1
[Line 136] Aug 18 04:03:01 routelogic dhcpd[6528]: Database file: /var/db/dhcpd.leases
[Line 137] Aug 18 04:03:01 routelogic dhcpd[6528]: Copyright 2004-2021 Internet Systems Consortium.
[Line 138] Aug 18 04:03:01 routelogic dhcpd[6528]: PID file: /var/run/dhcpd.pid
[Line 139] Aug 18 04:03:01 routelogic dhcpd[6528]: All rights reserved.
[Line 140] Aug 18 04:03:01 routelogic dhcpd[6528]: For info, please visit https://www.isc.org/software/dhcp/
[Line 141] Aug 18 04:03:01 routelogic dhcpd[6528]: Wrote 0 class decls to leases file.
[Line 142] Aug 18 04:03:01 routelogic dhcpd[6528]: Wrote 0 deleted host decls to leases file.
[Line 143] Aug 18 04:03:01 routelogic dhcpd[6528]: Wrote 0 new dynamic host decls to leases file.
[Line 144] Aug 18 04:03:01 routelogic dhcpd[6528]: Wrote 104 leases to leases file.
[Line 145] Aug 18 04:03:01 routelogic dhcpd[6528]: Listening on BPF/em1/74:46:a0:a5:95:e7/10.1.0.0/24
[Line 146] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   BPF/em1/74:46:a0:a5:95:e7/10.1.0.0/24
[Line 147] Aug 18 04:03:01 routelogic dhcpd[6528]: Listening on BPF/vmx0.6/00:50:56:be:00:02/10.6.0.0/24
[Line 148] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   BPF/vmx0.6/00:50:56:be:00:02/10.6.0.0/24
[Line 149] Aug 18 04:03:01 routelogic dhcpd[6528]: Listening on BPF/vmx0.7/00:50:56:be:00:02/10.7.0.0/24
[Line 150] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   BPF/vmx0.7/00:50:56:be:00:02/10.7.0.0/24
[Line 151] Aug 18 04:03:01 routelogic dhcpd[6528]: Listening on BPF/vmx0.9/00:50:56:be:00:02/10.9.0.0/24
[Line 152] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   BPF/vmx0.9/00:50:56:be:00:02/10.9.0.0/24
[Line 153] Aug 18 04:03:01 routelogic dhcpd[6528]: Listening on BPF/vmx0.11/00:50:56:be:00:02/10.11.11.0/24
[Line 154] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   BPF/vmx0.11/00:50:56:be:00:02/10.11.11.0/24
[Line 155] Aug 18 04:03:01 routelogic dhcpd[6528]: Sending on   Socket/fallback/fallback-net
[Line 156] Aug 18 04:03:01 routelogic dhcpd[6528]: Server starting service.

I cut out consecutive DORA entires leaving the first and last of each sequence, line numbers show the jumpst There are two allegedly non-responding NTP servers, one is the "old" PBX appliance, only old because it was replaced for a virtual one, but it is a very capable, modern device that has no other job than NTP. The other one it the only physical domain controller, also dedicated without any load nor Defender to prevent it from responding. Both servers are on different VLANs from each other and my computer, pfSense connects it all. I can ping them both from my zone.

All tagged interfaces are children of a single VMXNET 3 NIC, i.e. vmx0.2-4094. It's uses hypervisor-intervention-minimal LACP to connect out to physical. Untagged VLAN 1 (AKA VLAN zero) goes out via a passedthrough NIC doubling an emergency direct port to the firewall for assorted screw ups:

I'd suck it up and use AD with pfSense as a relay but at some point I'd get a crashing DHCP relay as well, actually, it doesn't even need to be AD for the relay to crash it can be Mikrotik's CHR or even another pfSense box, it just happens. As authoritative DHCP, this is the first time, though.

Where else can I look for causes of the restarts?

Restarting the service from the GUI stabilizes it a little making the crashes farther apart but I think I will have to switch to my phone's connection to post this though. At least I have options but it sucks that I edited the XML by hand to have the perfect, non-rushed DHCP table with placeholders for devices that don't even exist.

If any of the Redmine devs are reading this, I'd be happy to post whatever logs or config you need if it's helpful to do your pf wizardry. I forgot my username on Redmine. :P

senseivita

@skilledinept It wasn't all that difficult putting the leases into a PowerShell script now that they're super tidy. :) Still, pfSense UI, which is rather clunky and slow beats from the oldest MMC, to IPAM, SCCM to the newest W Admin Center. PowerShell, surprisingly, the best because you can wipe all and load from a text file UNIX-style all within a VS Code window, RDS is still needed though. I thought it was going to be another couple of days copying MAC addresses. :/. It's mind blowing that this OS is a serious product.

If anyone knows how to fix it though, I'd still like to attempt that. :)