Dhcpd stopped working after 2.1.2 latest upgrade



  • I upgraded to the latest 2.1.2 post-ssl-bug version and DHCP has stopped working on my LAN interface, so only machines which are configured with static addresses on the client side are able to talk to the network. Any machine which was previously set to get it's IP from the pfsense box using DHCP is unable to communicate with the network.
    The logs for DHCP show that the daemon is failing to start, and attempting to restart it using the GUI (Status>Services - click the arrow to start the service) fail.
    The logs below show it failing (sorry about the reverse order - that is how they come up in the logs section):

    Apr 14 20:39:59 dhcpd: exiting.
    Apr 14 20:39:59 dhcpd: 
    Apr 14 20:39:59 dhcpd: the README file.
    Apr 14 20:39:59 dhcpd: send them to the appropriate mailing list as described in
    Apr 14 20:39:59 dhcpd: help directly to the authors of this software - please
    Apr 14 20:39:59 dhcpd: Please do not under any circumstances send requests for
    Apr 14 20:39:59 dhcpd: 
    Apr 14 20:39:59 dhcpd: submitting bug reports and requests for help.
    Apr 14 20:39:59 dhcpd: mailing list, please read the section on the README about
    Apr 14 20:39:59 dhcpd: If you intend to request help from the dhcp-bugs at isc.org
    Apr 14 20:39:59 dhcpd: yet read the README, please read it before requesting help.
    Apr 14 20:39:59 dhcpd: If you did get this software from ftp.isc.org and have not
    Apr 14 20:39:59 dhcpd: 
    Apr 14 20:39:59 dhcpd: requesting help.
    Apr 14 20:39:59 dhcpd: get the latest from ftp.isc.org and install that before
    Apr 14 20:39:59 dhcpd: If you did not get this software from ftp.isc.org, please
    Apr 14 20:39:59 dhcpd: 
    Apr 14 20:39:59 dhcpd: There's already a DHCP server running.
    Apr 14 20:39:59 dhcpd: Sending on Socket/fallback/fallback-net
    Apr 14 20:39:59 dhcpd: Sending on BPF/rl1/00:30:18:4c:5d:09/192.168.64.0/24
    Apr 14 20:39:59 dhcpd: Listening on BPF/rl1/00:30:18:4c:5d:09/192.168.64.0/24
    Apr 14 20:39:59 dhcpd: Sending on BPF/em1/00:30:18:4a:a4:55/192.168.72.0/24
    Apr 14 20:39:59 dhcpd: Listening on BPF/em1/00:30:18:4a:a4:55/192.168.72.0/24
    Apr 14 20:39:59 dhcpd: Sending on BPF/em2/00:30:18:4a:a4:56/192.168.28.0/24
    Apr 14 20:39:59 dhcpd: Listening on BPF/em2/00:30:18:4a:a4:56/192.168.28.0/24
    Apr 14 20:39:59 dhcpd: Wrote 1 leases to leases file.
    Apr 14 20:39:59 dhcpd: Wrote 0 new dynamic host decls to leases file.
    Apr 14 20:39:59 dhcpd: Wrote 0 deleted host decls to leases file.
    Apr 14 20:39:59 dhcpd: For info, please visit https://www.isc.org/software/dhcp/
    Apr 14 20:39:59 dhcpd: All rights reserved.
    Apr 14 20:39:59 dhcpd: Copyright 2004-2014 Internet Systems Consortium.
    Apr 14 20:39:59 dhcpd: Internet Systems Consortium DHCP Server 4.2.6
    Apr 14 20:39:59 dhcpd: For info, please visit https://www.isc.org/software/dhcp/
    Apr 14 20:39:59 dhcpd: All rights reserved.
    Apr 14 20:39:59 dhcpd: Copyright 2004-2014 Internet Systems Consortium.
    Apr 14 20:39:59 dhcpd: Internet Systems Consortium DHCP Server 4.2.6
    Apr 14 20:36:38 dhcpd: exiting.



  • A few more details.

    During boot one of the lines scrolling through the screen says:
    "Invalid pid in file /var/dhcpd/var/run/dhcp.pid"

    /var/log/system.log has some entries which say:
    pfot dhcpleases: Could not deliver signal HUP to process because its pid file does not exist. No such file or directory



  • This is the reason:

    Apr 14 20:39:59 dhcpd: There's already a DHCP server running. 
    

    The question is, why?
    I think it means there is already a DHCP server running on this machine. That should not be able to happen. Or maybe somehow DHCP Relay has also got enabled?
    What was interesting about your DHCP configuration and/or system in general that might be a bit unusual?



  • Thanks for the input!

    I think I may have solved it. I deleted the /var/dhcpd/var/run/dhcp.pid file and was able to restart the dhcp service from the GUI using a machine that had a fixed IP address (and thus did not depend on DHCP and was able to let me run the GUI).

    I suspect what normally happens is that the dhcpd daemon cleans up after itself and removes its pid file when it stops, but for some reason I cannot fathom this did not happen during the upgrade. Then, when the system boots and tries to start dhcpd it finds that there is already a dhcpd.pid file, so it complains about it and does not start dhcpd.

    The log messages about "There's already a DHCP server running." is therefore incorrect (you can do ps ax |grep dhcp to check) but probably caused by some process seeing there is a dhcpd.pid FILE and therefore ASSUMING that a dhcpd PROCESS must be running given there is a pid file for it.

    It may be worth checking why this occurred as it if happened to me it may happen to others who might end up flummoxed by the unusual behavior and the odd cure (rebooting does not cure it - you need to know to delete the pid file). I upgraded a second identical machine (same hardware but slightly different configuration - one was HQ and the other was a branch office tunneling into HQ), and the second machine upgraded without any issue, so it seems to be a sporadic fault from my own statistically insignificant sample of two units.



  • [[NEVERMIND, I HAD A FAILING SWITCH ADJACENT TO FIREWALL]]

    I have the exact same problem.

    DHCPD says it's running but no clients are given addresses.

    After stopping the DHCP Server found 2 PID files in```
    /var/dhcpd/var/run

    
    

    [2.1.2-RELEASE][root@pfsense.amc.localdomain]/var/dhcpd/var/run(3): ls -ahl
    total 8
    drwxr-xr-x  2 dhcpd  _dhcp  512B Apr 21 15:35 .
    drwxr-xr-x  4 dhcpd  _dhcp  512B Nov 11  2012 ..
    -rw-r--r--  1 dhcpd  _dhcp    6B Apr 22 06:32 dhcpd.pid
    -rw-r--r--  1 dhcpd  _dhcp    5B Sep 26  2013 dhcpdv6.pid
    srw-rw-rw-  1 dhcpd  _dhcp    0B Apr 21 15:35 log

    
    Rebooting doesn't help.
    
    After deleting stale PID files and starting DHCP Server, one dhcpd.pid file appears.