DHCP problem

sorvani · Jan 31, 2010, 6:18 AM

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

GruensFroeschli · Jan 31, 2010, 7:21 AM

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.

sorvani · Feb 1, 2010, 12:46 AM

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.

cb831 · May 20, 2010, 9:54 PM

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

wallabybob · May 21, 2010, 4:59 AM

@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.

cb831 · May 21, 2010, 5:17 AM

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

???

wallabybob · May 21, 2010, 5:40 AM

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.)

cb831 · May 21, 2010, 8:14 AM

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 ?

wallabybob · May 21, 2010, 11:03 AM

@cb831:

Any Ideas ?

Something wrong with my earlier suggestions?

cb831 · May 21, 2010, 10:17 PM

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

cb831 · May 22, 2010, 12:37 AM

Looks like this is the same issue

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

cb831 · May 22, 2010, 1:01 AM

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.

wallabybob · May 22, 2010, 7:18 AM

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

cb831 · May 22, 2010, 8:33 AM

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

wallabybob · May 22, 2010, 8:47 AM

Understood, thanks.

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

cb831 · May 22, 2010, 8:49 AM

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 ?

wallabybob · May 22, 2010, 10:04 AM

pfSense 1.2.3 is based on FreeBSD 7.2

cb831 · May 22, 2010, 5:48 PM

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

cb831 · May 25, 2010, 3:59 PM

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

Tuckie · Aug 16, 2010, 9:33 PM

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.