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 100baseTXPublic 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/24Jan 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.47When 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:41If 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 vr0Is there anything wrong with my rules do I explicitely need to allow the incoming reply ?
Thanks
Claus -
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 ?
-
-
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 67Instead 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 67Hopefully it won't be dropping now.
