DHCP problem



  • Several time a day I will suddenly see Chrome displaying "Resolving Host" down in the status. Looking at the log when it happens, I see the WAN interface restarting. Can someone point me in the right troubleshooting direction?

    WAN interface
    IP address	 75.20.151.141  
    Subnet mask	 255.255.252.0
    Gateway	 75.20.148.1
    ISP DNS servers	 10.0.0.254
    Media	 100baseTX 
    

    Public IP from AT&T: 75.20.151.141
    LAN IP of 2Wire 10.0.0.254/24
    LAN Network of 2Wire: 10.0.0.0/24

    Jan 31 00:07:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 31 00:07:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 31 00:07:32	dhclient[48305]: SENDING DIRECT
    Jan 31 00:07:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 31 00:02:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 31 00:02:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 31 00:02:32	dhclient[48305]: SENDING DIRECT
    Jan 31 00:02:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:57:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:57:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:57:32	dhclient[48305]: SENDING DIRECT
    Jan 30 23:57:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:52:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:52:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:52:32	dhclient[48305]: SENDING DIRECT
    Jan 30 23:52:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:50:48	dnsmasq[48369]: reading /var/dhcpd/var/db/dhcpd.leases
    Jan 30 23:47:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:47:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:47:32	dhclient[48305]: SENDING DIRECT
    Jan 30 23:47:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:42:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:42:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:42:32	dhclient[48305]: SENDING DIRECT
    Jan 30 23:42:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:39:35	dnsmasq[48369]: reading /var/dhcpd/var/db/dhcpd.leases
    Jan 30 23:37:33	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:37:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:37:32	dhclient[48305]: SENDING DIRECT
    Jan 30 23:37:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:32:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:32:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 30 23:32:31	dhclient[48305]: SENDING DIRECT
    Jan 30 23:32:31	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:27:37	check_reload_status: reloading filter
    Jan 30 23:27:37	php: : rc.newwanip working with (IP address: 75.20.151.141) (interface: wan) (interface real: dc0).
    Jan 30 23:27:37	php: : Informational: rc.newwanip is starting dc0.
    Jan 30 23:27:36	dnsmasq[48369]: reading /var/dhcpd/var/db/dhcpd.leases
    Jan 30 23:27:36	check_reload_status: rc.newwanip starting
    Jan 30 23:27:36	php: : Processing -
    Jan 30 23:27:36	php: : Processing start -
    Jan 30 23:27:35	dhcpd: For info, please visit http://www.isc.org/sw/dhcp/
    Jan 30 23:27:35	dhcpd: All rights reserved.
    Jan 30 23:27:35	dhcpd: Copyright 2004-2008 Internet Systems Consortium.
    Jan 30 23:27:35	dhcpd: Internet Systems Consortium DHCP Server V3.0.7
    Jan 30 23:27:34	dnsmasq[48369]: read /etc/hosts - 15 addresses
    Jan 30 23:27:34	dnsmasq[48369]: using nameserver 8.8.8.8#53
    Jan 30 23:27:34	dnsmasq[48369]: using nameserver 8.8.4.4#53
    Jan 30 23:27:34	dnsmasq[48369]: reading /etc/resolv.conf
    Jan 30 23:27:34	dnsmasq[48369]: reading /var/dhcpd/var/db/dhcpd.leases
    Jan 30 23:27:34	dnsmasq[48369]: compile time options: IPv6 GNU-getopt BSD-bridge ISC-leasefile no-DBus no-I18N TFTP
    Jan 30 23:27:34	dnsmasq[48369]: started, version 2.45 cachesize 150
    Jan 30 23:27:33	dnsmasq[46749]: exiting on receipt of SIGTERM
    Jan 30 23:27:33	php: : phpDynDNS: (Success) IP Address Changed Successfully! (75.20.151.141)
    Jan 30 23:27:33	php: : phpDynDNS: updating cache file /cf/conf/dyndns.cache: 75.20.151.141
    Jan 30 23:27:33	php: : DynDns: Current Service: dyndns
    Jan 30 23:27:33	php: : DynDns: DynDns _checkStatus() starting.
    Jan 30 23:27:32	php: : DynDns: DynDns _update() starting. Dynamic
    Jan 30 23:27:32	php: : DynDns: DynDns _update() starting.
    Jan 30 23:27:32	php: : DynDns: More than 25 days. Updating.
    Jan 30 23:27:32	php: : DynDns: Cached IP: 75.20.151.141
    Jan 30 23:27:32	php: : DynDns: Current WAN IP: 75.20.151.141
    Jan 30 23:27:32	php: : DynDns: _detectChange() starting.
    Jan 30 23:27:32	php: : DynDns: updatedns() starting
    Jan 30 23:27:32	php: : DynDns: Running updatedns()
    Jan 30 23:27:31	dhclient[48253]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:27:31	dhclient[48253]: DHCPACK from 75.20.148.1
    Jan 30 23:27:30	dhclient[48253]: DHCPREQUEST on dc0 to 255.255.255.255 port 67
    Jan 30 23:27:29	dhclient[46650]: exiting.
    Jan 30 23:27:29	dhclient[46650]: exiting.
    Jan 30 23:27:29	dhclient[46650]: connection closed
    Jan 30 23:27:29	dhclient[46650]: connection closed
    Jan 30 23:27:26	php: : HOTPLUG: Configuring wan interface dc0
    Jan 30 23:27:26	php: : DEVD Ethernet attached event for dc0
    Jan 30 23:27:26	php: : Processing dc0 - start
    Jan 30 23:27:25	check_reload_status: rc.linkup starting
    Jan 30 23:27:24	kernel: dc0: link state changed to UP
    Jan 30 23:27:23	kernel: dc0: link state changed to DOWN
    Jan 30 23:26:25	php: : rc.newwanip working with (IP address: 75.20.151.141) (interface: wan) (interface real: dc0).
    Jan 30 23:26:25	php: : Informational: rc.newwanip is starting dc0.
    Jan 30 23:26:24	check_reload_status: rc.newwanip starting
    Jan 30 23:26:06	last message repeated 18 times
    Jan 30 23:26:20	dhclient[46701]: bound to 75.20.151.141 -- renewal in 300 seconds.
    Jan 30 23:26:19	dhclient[46701]: DHCPACK from 75.20.148.1
    Jan 30 23:26:19	dhclient[46701]: DHCPREQUEST on dc0 to 255.255.255.255 port 67
    Jan 30 23:26:17	dhclient[46701]: DHCPOFFER from 10.0.0.254
    Jan 30 23:26:16	dhclient[46701]: DHCPDISCOVER on dc0 to 255.255.255.255 port 67 interval 2
    Jan 30 23:24:30	dhclient[46701]: SENDING DIRECT
    Jan 30 23:24:30	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:23:21	dhclient[46701]: SENDING DIRECT
    Jan 30 23:23:21	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:22:39	dhclient[46701]: SENDING DIRECT
    Jan 30 23:22:39	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:22:15	dhclient[46701]: SENDING DIRECT
    Jan 30 23:22:15	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:21:55	dhclient[46701]: SENDING DIRECT
    Jan 30 23:21:55	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:21:40	dhclient[46701]: SENDING DIRECT
    Jan 30 23:21:40	dhclient[46701]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 30 23:21:30	dhclient[46701]: SENDING DIRECT
    


  • Your ISP has an unusual low expiration time.

    300 seconds is only 5 minutes.
    Normally this is more in the range of 60~1440 minutes.

    If you happen to try to request something while the IP is renewed you will observe the described behaviour.

    You will have to call your ISP and ask if they can increase the expiration time.



  • Ok did a little more testing then. Looks like I get to deal with outsourced tech support…....... :(

    Since DHCP normally will try to renew at half of the Lease time, I am going to assume that I am getting a 10 minute lease, and that pfSense is showing the renew time in 300 seconds because that is half of the lease.

    As I noted this is hooked up to a port on my 2Wire home portal from AT&T U-Verse and marked as the DMZ.

    
    Model:	3800HGV-B Gateway
    Serial Number:	460711154442
    Hardware Version:	2700-100531-006
    Software Version:	5.29.135.47
    
    

    When I change the DMZ to be my laptop It also shows a 10 minute lease.

    Ethernet adapter Wireless Network Connection:
    
            Connection-specific DNS Suffix  . : gateway.2wire.net
            Description . . . . . . . . . . . : Intel(R) PRO/Wireless 3945ABG Networ
    k Connection
            Physical Address. . . . . . . . . : 00-13-02-08-29-4B
            Dhcp Enabled. . . . . . . . . . . : Yes
            Autoconfiguration Enabled . . . . : Yes
            IP Address. . . . . . . . . . . . : 75.20.151.141
            Subnet Mask . . . . . . . . . . . : 255.255.252.0
            Default Gateway . . . . . . . . . : 75.20.148.1
            DHCP Server . . . . . . . . . . . : 10.0.0.254
            DNS Servers . . . . . . . . . . . : 10.0.0.254
            Lease Obtained. . . . . . . . . . : Sunday, January 31, 2010 18:29:41
            Lease Expires . . . . . . . . . . : Sunday, January 31, 2010 18:39:41
    
    

    If I change either unit to just get a normal IP from the LAN of the 2Wire, then I get the default 24 hours lease.



  • I see the same thing - my ISP insist on having 300s leases which means that the lease must be renewed already after 150s.

    When I snif the DHCP packages I notice that the "SENDING DIRECT" does not originate from port 68 like the normal broadcast. However my IPS DHCP server do answer the DIRECT renewal but the FW does not seam to pick it up and it falls back to broadcast after 7 attempts of direct. When it broadcast I sometimes loses 3s of communication :-( and now the problem starts as my wife gets 3s dropouts on the sip phone :-).

    How can I verify if the FW picks up the direct reply ? I see in the log

    dhclient[41748]: DHCPREQUEST on vr0 to 255.255.255.255 port 67
    May 20 23:39:39 dhclient[41748]: DHCPACK from 79.142.231.1
    May 20 23:39:39 dhclient[41748]: bound to 79.142.231.106 – renewal in 150 seconds.
    May 20 23:42:09 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:42:09 dhclient[41748]: SENDING DIRECT
    May 20 23:42:17 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:42:17 dhclient[41748]: SENDING DIRECT
    May 20 23:42:28 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:42:28 dhclient[41748]: SENDING DIRECT
    May 20 23:42:35 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:42:35 dhclient[41748]: SENDING DIRECT
    May 20 23:42:57 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:42:57 dhclient[41748]: SENDING DIRECT
    May 20 23:43:20 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:43:20 dhclient[41748]: SENDING DIRECT
    May 20 23:43:56 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:43:56 dhclient[41748]: SENDING DIRECT
    May 20 23:44:40 dhclient[41748]: DHCPDISCOVER on vr0 to 255.255.255.255 port 67 interval 8
    May 20 23:44:40 dhclient[41748]: DHCPOFFER from 79.142.231.1
    May 20 23:44:42 dhclient[41748]: DHCPREQUEST on vr0 to 255.255.255.255 port 67
    May 20 23:44:42 dhclient[41748]: DHCPACK from 79.142.231.1
    May 20 23:44:42 dhclient[41748]: bound to 79.142.231.106 – renewal in 150 seconds.
    May 20 23:44:47 check_reload_status: rc.newwanip starting
    May 20 23:44:49 php: : Informational: rc.newwanip is starting .
    May 20 23:44:49 php: : rc.newwanip working with (IP address: 79.142.231.106) (interface: wan) (interface real: vr0).
    May 20 23:47:12 dhclient[41748]: DHCPREQUEST on vr0 to 79.142.231.1 port 67
    May 20 23:47:12 dhclient[41748]: SENDING DIRECT
    May 20 23:47:19 dhclient[41748]: DHCPREQUEST on vr0

    Is there anything wrong with my rules do I explicitely need to allow the incoming reply ?

    Thanks
    Claus



  • @cb831:

    Is there anything wrong with my rules do I explicitely need to allow the incoming reply ?

    If you see the DHCP reply in your sniffer I suggest you run a packet trace on your WAN interface to verify its being correctly received. Then see if the DHCP reply matches any of the firewall rules on your WAN. If so, you will need to add a rule to allow those replies. You could also look in the firewall log (Status -> System Logs, click on Firewall tab) to see the if firewall is dropping them with logging, but this is not coclusive because the firewall might be dropping them without logging.



  • What would the above log look like if ok ?

    Something like

    DHCPREQUEST on vr0 to 255.255.255.255 port 67 
    DHCPACK from 79.142.231.1 
    bound to 79.142.231.106 -- renewal in 150 seconds. 
    
    DHCPREQUEST on vr0 to 79.142.231.1 port 67 
    SENDING DIRECT 
    bound to 79.142.231.106 -- renewal in 150 seconds. 
    
    repeat above 3 every 150s
    

    ???



  • Sorry, I don't have a record of dhclient extending a lease in my system logs, but I would guess it would look something like what you provided. (My WAN link has its IP address provided by DHCP.)



  • Reading initial post I guess it should look like

    Jan 31 00:07:32	dhclient[48305]: DHCPREQUEST on dc0 to 10.0.0.254 port 67
    Jan 31 00:07:32	dhclient[48305]: SENDING DIRECT
    Jan 31 00:07:32	dhclient[48305]: DHCPACK from 75.20.148.1
    Jan 31 00:07:32	dhclient[48305]: bound to 75.20.151.141 -- renewal in 300 seconds.
    

    and I do not get the ACK meaning that my FW does not recoqnize the ACK eventhough I can see it on the wire.

    Any Ideas ?



  • @cb831:

    Any Ideas ?

    Something wrong with my earlier suggestions?



  • Certainly not :-)

    But I did look into the logs and see that the FW does not recognize the direct dhcp ack.
    I also checked the fw log and I see no drops (all my rules are logging including the default drop).
    And I tried to allow anything from my DHCP server on the WAN interface.

    But I still see the issue.

    I tried to configure a CISCO 806 with ip address dhcp and it works like a charm. So problem must be that pfSense does not recoqnize the ack on the direct renew…
    Is that a pfSense issue or an issue in the underlying FreeBSD ?

    Thanks
    Claus



  • Looks like this is the same issue

    http://forum.pfsense.org/index.php?topic=19149.0;wap2



  • GOT IT:

    There is an error in the FreeBSD implementation of dhclient. If I substitute the 70 dhclient with the 80 ditto the protocol runs smoothly

    arc01fw03:/var#  ./dhclient -d sis3
    DHCPREQUEST on sis3 to 255.255.255.255 port 67
    DHCPACK from 79.142.231.1
    bound to 79.142.231.106 – renewal in 150 seconds.
    DHCPREQUEST on sis3 to 79.142.231.1 port 67
    DHCPACK from 79.142.231.1
    bound to 79.142.231.106 -- renewal in 150 seconds.



  • I don't understand what you mean by the 70 dhclient. Would you please explain?



  • I mean the /sbin/dhclient executable which runs the dhcp client logic.
    If I replace this executable (which is based on FreeBSD 7.0 for pfSense 1.2.2) with the FreeBSD 8.0 executable it works as my previous post indicates.

    As of now the 8.0 dhclient has renewed successfully without broadcast for 8h :-)

    So now I just need to find out how to replace dhclient in /sbin which is R/O on my CFCARD. Right now i killed the /sbin/dhclient and run the 8.0 version out of /var on the pfSense command line.

    Thanks



  • Understood, thanks.

    Have you tried pfSense 1.2.3, which is rather more up to date than pfSense 1.2.2?



  • Actually I'm awaiting 2.0 but maybe this was a wrong strategy.

    Also found http://www.pubbs.net/200902/freebsd/23740-dhclient-cant-renew-lease.html which suggests replacing the 7.0 dhclient with the 7.1 counterpart.

    Is 1.2.3 FreeBSD 7.1 based ?



  • pfSense 1.2.3 is based on FreeBSD 7.2



  • I just installed 1.2.3 Nano 2G image on my CFCard and except for problems assigning interfaces to WAN and LAN and LAN IP address using the console (it ignored my input :-/) I managed to restore my configuration by assigning IP 192.168.1.2 to my own machine.

    Now everything - including dhcp - seems to be fine :-)

    Thanks for the input !!

    Claus



  • UPDATE:

    Upgrading to 1.2.3 was not enough to remove the failures renewing directly.
    However substituting the /sbin/dhclient with the dhclient from FreeBSD 8.0 did the trick.

    Thanks
    Claus



  • Anyone have a copy of dhclient from 8.0 that they'd be willing to send me?

    Thanks in advance, and much kudos to cb831!

    edit: I got impatient so I downloaded the 220MB iso to extract the 77K file ;)

    It appears to be working, I'm now getting:
    Aug 16 17:30:35 dhclient[63382]: bound to 99.99.207.xxx – renewal in 300 seconds.
    Aug 16 17:30:35 dhclient[63382]: DHCPACK from 99.99.206.xxx
    Aug 16 17:30:35 dhclient[63382]: DHCPREQUEST on vlan0 to 10.0.0.1 port 67

    Instead of:
    Aug 16 17:11:03 dhclient[18353]: bound to 99.99.207.xxx – renewal in 300 seconds.
    Aug 16 17:11:03 dhclient[18353]: DHCPACK from 99.99.206.xxx
    Aug 16 17:11:03 dhclient[18353]: SENDING DIRECT
    Aug 16 17:11:03 dhclient[18353]: DHCPREQUEST on vlan0 to 10.0.0.1 port 67

    Hopefully it won't be dropping now.


Log in to reply