Keep loosing WAN IP Address - dhclient does not seem to do update

Selective · Mar 14, 2007, 1:27 PM

removing snort won´t change a thing, he got the same error i do,and i don´t use snort. And as i said it only happens one time after reboot, pressing the renew button clears the problem.

the dhclient error is not fixed !

Veni · Mar 14, 2007, 2:48 PM

I removed Snort a couple of hours ago, and will give it a go
try to reproduce the issue by rebooting the pfSense computer
and not reinstalling Snort for a while.

sullrich · Mar 14, 2007, 7:35 PM

@Selective:

removing snort won´t change a thing, he got the same error i do,and i don´t use snort. And as i said it only happens one time after reboot, pressing the renew button clears the problem.

the dhclient error is not fixed !

Calm down there pal. Snort gets RELOADED at the same time that dhclient invokes… So you don't know what your talking about quite frankly.

Veni · Mar 15, 2007, 7:37 AM

Alright, it happened again a couple of minutes ago.
Pressing the Renew button gave me back my ipaddress within 5 seconds.
Checked traffic on my WatchGuard box and it did not record any problem with the internet.

I pressed the Renew button around 08:27.

This is what i have from syslog:

Mar 15 07:00:57 last message repeated 4 times
Mar 15 07:01:30 dhclient[269]: DHCPREQUEST on xl1 to 255.255.255.255 port 67
Mar 15 07:01:30 dhclient[269]: DHCPACK from 81.236.128.1
Mar 15 07:01:31 dhclient[269]: bound to 81.236.134.30 – renewal in 600 seconds.
Mar 15 07:11:30 dhclient[269]: DHCPREQUEST on xl1 to 81.228.3.186 port 67
Mar 15 07:12:01 last message repeated 3 times
Mar 15 07:14:07 last message repeated 4 times
Mar 15 07:18:51 last message repeated 12 times
Mar 15 07:19:58 dhclient[269]: DHCPREQUEST on xl1 to 255.255.255.255 port 67
Mar 15 07:19:58 dhclient[269]: DHCPACK from 81.236.128.1
Mar 15 07:19:59 dhclient[269]: bound to 81.236.134.30 – renewal in 600 seconds.
Mar 15 07:29:58 dhclient[269]: DHCPREQUEST on xl1 to 81.228.3.186 port 67
Mar 15 07:30:26 last message repeated 2 times
Mar 15 07:32:35 last message repeated 4 times
Mar 15 07:36:11 last message repeated 3 times
Mar 15 07:39:59 dhclient[269]: DHCPDISCOVER on xl1 to 255.255.255.255 port 67 interval 7
Mar 15 07:40:06 dhclient[269]: DHCPDISCOVER on xl1 to 255.255.255.255 port 67 interval 15
Mar 15 07:40:06 dhclient[269]: DHCPOFFER from 81.236.128.1
Mar 15 07:40:08 dhclient[269]: DHCPREQUEST on xl1 to 255.255.255.255 port 67
Mar 15 07:40:08 dhclient[269]: DHCPACK from 81.236.128.1
Mar 15 07:40:08 dhclient[269]: bound to 81.236.134.30 – renewal in 600 seconds.
Mar 15 07:42:02 dnsmasq[529]: reading /etc/resolv.conf
Mar 15 07:42:02 dnsmasq[529]: using nameserver 195.67.199.41#53
Mar 15 07:42:02 dnsmasq[529]: using nameserver 195.67.199.40#53
Mar 15 07:42:02 dnsmasq[529]: using nameserver 195.67.199.39#53
Mar 15 07:50:08 dhclient[269]: DHCPREQUEST on xl1 to 81.228.3.186 port 67
Mar 15 07:50:38 last message repeated 3 times
Mar 15 07:52:41 last message repeated 5 times
Mar 15 07:55:06 dhclient[269]: DHCPREQUEST on xl1 to 81.228.3.186 port 67
Mar 15 08:00:10 dhclient[269]: DHCPDISCOVER on xl1 to 255.255.255.255 port 67 interval 3
Mar 15 08:00:10 dhclient[269]: DHCPOFFER from 81.236.128.1
Mar 15 08:00:12 dhclient[269]: DHCPREQUEST on xl1 to 255.255.255.255 port 67
Mar 15 08:00:12 dhclient[269]: DHCPACK from 81.236.128.1
Mar 15 08:00:12 dhclient[269]: bound to 81.236.134.30 – renewal in 600 seconds.
Mar 15 08:01:33 dnsmasq[529]: reading /etc/resolv.conf
Mar 15 08:01:33 dnsmasq[529]: using nameserver 195.67.199.41#53
Mar 15 08:01:33 dnsmasq[529]: using nameserver 195.67.199.40#53
Mar 15 08:01:33 dnsmasq[529]: using nameserver 195.67.199.39#53
Mar 15 08:10:12 dhclient[269]: DHCPREQUEST on xl1 to 81.228.3.186 port 67
Mar 15 08:10:33 last message repeated 2 times
Mar 15 08:11:41 last message repeated 4 times
Mar 15 08:15:34 last message repeated 2 times
Mar 15 08:20:13 dhclient[269]: short write: wanted 22 got 0 bytes
Mar 15 08:20:13 dhclient[269]: exiting.
Mar 15 08:27:37 dhclient[68835]: DHCPDISCOVER on xl1 to 255.255.255.255 port 67 interval 8
Mar 15 08:27:37 dhclient[68835]: DHCPOFFER from 81.236.128.1
Mar 15 08:27:39 dhclient[68835]: DHCPREQUEST on xl1 to 255.255.255.255 port 67
Mar 15 08:27:39 dhclient[68835]: DHCPACK from 81.236.128.1
Mar 15 08:27:40 dhclient[68835]: bound to 81.236.134.30 – renewal in 600 seconds.
Mar 15 08:27:42 login: login on ttyv0 as root
Mar 15 08:28:03 dnsmasq[529]: reading /etc/resolv.conf
Mar 15 08:28:03 dnsmasq[529]: using nameserver 195.67.199.41#53
Mar 15 08:28:03 dnsmasq[529]: using nameserver 195.67.199.40#53
Mar 15 08:28:03 dnsmasq[529]: using nameserver 195.67.199.39#53

sullrich · Mar 15, 2007, 4:19 PM

We REALLY wish that we could reproduce this… Everything we have tried does not reproduce it :(

Veni · Mar 16, 2007, 1:17 PM

Is there a way of asking dhclient to produce more info for debugging purposes?
I would glady run it in a mode like that :).

I don't really know what short write is, but from the looks of it, is it possible
to alter dhclient so that it does not invoke a shutdown of it self when the
short write event occurs?

??? What is short write?
??? What is the criteria for triggering that kind of response from the dhclient?

Selective, it would be interesting to know what country you are from and what
ISP you are using plus what type of physical connection the ISP delivers to you.

My ISP is TeliaSonera in Sweden and they deliver my internetaccess to a standard
RJ45 LAN Cat5(e?) port.

Selective · Mar 16, 2007, 3:39 PM

im using telia as well, but through ADSL.

The strange thing is that it only happens once, after reboot, so it must be something wrong with boot process..

sullrich · Mar 16, 2007, 4:11 PM

I doubt it has anything to do with the boot sequence.

Short writes in this case is the privilege separation code. This appears to be a deep FreeBSD bug of some sort.

Krakke · Mar 19, 2007, 9:11 PM

sullrich thank you :D

Version 1.0.1-SNAPSHOT-03-08-2007
Uptime 7 days, 13:06

Still running! Time to close this thread?

Ethernet connection 100/10 megabits (ISP BBB Sweden)

my own little world http://www.krakke.com/bilder/serverrum/IMG_6725_th_ex.jpg ;)

UrbanSk · Mar 20, 2007, 7:38 AM

Hi all!

I just jumped in to this tread as i experience the same problem.
After a reboot the wan interface looses its IP-adress. A renew fixes it until the next reboot.

My version:
1.0.1-SNAPSHOT-03-08-2007
built on Sat Mar 10 00:05:34 EST 2007

Selective and Veni uses Telia as ISP just as i am.

Can the problem be related to our ISP hense you can not reproduce the problem.

My knowledge of FreeBSD is limited but I will assist in any way I can if needed.

Found some new information on this link:

http://www.clavister.com/support/kb/10078/

Regards,

UrbanSk

sullrich · Mar 20, 2007, 2:54 PM

Maybe one of you (or all) can call the ISP and ask them what is going on.

sai · Mar 22, 2007, 5:26 PM

from the Clavister site:

Symptom:
The firewall fails to receive an IP address from DHCP.

Note: The swedish ISP Telia has some servers that causes problems with the default settings. Changing the settings to the following is known to work in those cases:
DHCP_MinimumLeaseTime 60
DHCP_ValidateBcast NO
DHCP_AllowGlobalBcast YES
DHCP_UseLinkLocalIP NO
DHCP_DisableArpOnOffer NO

Veni · Mar 23, 2007, 12:32 PM

This is what i found about the options mentioned above:

DHCP_MinimumLeaseTime
Minimum lease time (seconds) accepted from the DHCP server.

Default: 60

DHCP_ValidateBcast
Require that the assigned broadcast address is the highest address in the assigned network

Default: Enabled

DHCP_AllowGlobalBcast
Allow DHCP server to assign 255.255.255.255 as broadcast. (Non-standard.)

Default: Disabled

DHCP_UseLinkLocalIP
If this is enabled the firewall will use a Link Local IP (169.254..) instead of 0.0.0.0 while waiting for a lease.

Default: Disabled

DHCP_DisableArpOnOffer
Disable the arp check done by the firewall on the offered IP.

DHCP client can now be configured to not check for IP conflicts
Issue: The DHCP client normally checks if the IP address in an offer is already taken on the local network by performing an ARP query for it. However, some routers may ARP publish IP addresses while the DHCP transaction is running and cause false positives. One such example is the Clavister Firewall DHCP relayer before v8.30.01, in certain configurations. There are also others.
Change: As of v8.30.01, the DHCP client can be configured to not check for IP conflicts in offered leases via "Advanced Settings" -> "DHCP" -> "DHCP_DisableArpOnOffer".

Default: Disabled

The default settings in advanced settings->DHCP client is following:
DHCP_MinimumLeaseTime 60
DHCP_ValidateBcast YES
DHCP_AllowGlobalBcast NO
DHCP_UseLinkLocalIP NO
DHCP_DisableArpOnOffer NO

However. To have the firewall accept uncommon IP offers you might have to make adjustments on the settings.
DHCP_MinimumLeaseTime 60
DHCP_ValidateBcast NO
DHCP_AllowGlobalBcast YES
DHCP_UseLinkLocalIP NO
DHCP_DisableArpOnOffer YES

And then there is the one that sai posted about Clavister and TeliaSonera.

jeroen234 · Mar 27, 2007, 5:36 AM

so the problem is a isp that is having its dhcp server miss configured
shame on them

freax · Mar 27, 2007, 8:58 AM

My problem was solved.

I have a uptime with 17 days.

Thanks.

UrbanSk · Mar 28, 2007, 11:06 AM

Hi all! It happened for me again today.

Can someone help me confirm if the behaviour (below) is expected and that the ISP (Telia) might be blamed for missconfigured DHCP servers.

My system:
1.0.1-SNAPSHOT-03-23-2007
built on Mon Mar 26 21:03:58 EDT 2007

1. Reboot PFSense box
2. I get an IP on WAN from ISP
3. After several hours (approx 12) I loose IP on WAN.
4. Pressing "renew" on WAN interface will render me an new IP
5. I will get uptimes over several days until the next reboot and it starts from point 1 again.

Taken from system log:

Mar 28 11:57:58 dhclient: New Subnet Mask (vr0): 255.255.255.0
Mar 28 11:57:58 dhclient: New Broadcast Address (vr0): XX.YY.ZZ.255
Mar 28 11:57:58 dhclient: New Routers (vr0): XX.YY.ZZ.1
Mar 28 11:57:58 dhclient: Adding new routes
Mar 28 11:57:58 dhclient: /sbin/route add default XX.YY.ZZ.1
Mar 28 11:57:58 dhclient: Creating resolv.conf
Mar 28 11:57:59 dhclient: notify_rc_newwanip()
Mar 28 11:57:59 dhclient[328]: bound to XX.YY.ZZ.196 – renewal in 600 seconds.
Mar 28 12:07:58 dhclient[328]: DHCPREQUEST on vr0 to 212.181.166.82 port 67
Mar 28 12:16:45 dhclient[328]: DHCPREQUEST on vr0 to 255.255.255.255 port 67
Mar 28 12:16:45 dhclient[328]: DHCPACK from 81.231.254.1
Mar 28 12:16:45 dhclient[328]: short write: wanted 21 got 0 bytes
Mar 28 12:16:45 dhclient[328]: short write: wanted 21 got 0 bytes
Mar 28 12:16:45 dhclient[328]: exiting.
Mar 28 12:16:45 dhclient[328]: exiting.
Mar 28 12:39:23 dhclient: netstat
Mar 28 12:39:23 dhclient: PREINIT
Mar 28 12:39:23 dhclient: netstat
Mar 28 12:39:23 dhclient: EXPIRE
Mar 28 12:39:23 dhclient: Deleting old routes
Mar 28 12:39:23 dhclient: netstat
Mar 28 12:39:23 dhclient: PREINIT
Mar 28 12:39:23 dhclient[17151]: DHCPDISCOVER on vr0 to 255.255.255.255 port 67 interval 4
Mar 28 12:39:24 dhclient[17151]: DHCPOFFER from 81.231.254.1
Mar 28 12:39:24 dhclient: netstat
Mar 28 12:39:24 dhclient: ARPSEND
Mar 28 12:39:26 dhclient: netstat
Mar 28 12:39:26 dhclient: ARPCHECK
Mar 28 12:39:26 dhclient[17151]: DHCPREQUEST on vr0 to 255.255.255.255 port 67
Mar 28 12:39:26 dhclient[17151]: DHCPACK from 81.231.254.1
Mar 28 12:39:26 dhclient: netstat
Mar 28 12:39:26 dhclient: BOUND
Mar 28 12:39:26 dhclient: Starting add_new_address()
Mar 28 12:39:27 dhclient: ifconfig vr0 inet XX.YY.ZZ.196 netmask 255.255.255.0 broadcast XX.YY.ZZ.255
Mar 28 12:39:27 dhclient: New IP Address (vr0): XX.YY.ZZ.196
Mar 28 12:39:27 dhclient: New Subnet Mask (vr0): 255.255.255.0
Mar 28 12:39:27 dhclient: New Broadcast Address (vr0): XX.YY.ZZ.255
Mar 28 12:39:27 dhclient: New Routers (vr0): XX.YY.ZZ.1
Mar 28 12:39:27 dhclient: Adding new routes
Mar 28 12:39:27 dhclient: /sbin/route add default XX.YY.ZZ.1
Mar 28 12:39:27 dhclient: Creating resolv.conf
Mar 28 12:39:27 dhclient: notify_rc_newwanip()
Mar 28 12:39:27 dhclient[17151]: bound to XX.YY.ZZ.196 – renewal in 600 seconds.
Mar 28 12:49:26 dhclient[17248]: DHCPREQUEST on vr0 to 212.181.166.82 port 67
Mar 28 12:57:05 dhclient[17248]: DHCPREQUEST on vr0 to 255.255.255.255 port 67
Mar 28 12:57:05 dhclient[17248]: DHCPACK from 81.231.254.1
Mar 28 12:57:05 dhclient: netstat
Mar 28 12:57:05 dhclient: RENEW
Mar 28 12:57:05 dhclient: Creating resolv.conf
Mar 28 12:57:06 dhclient[17248]: bound to XX.YY.ZZ.196 – renewal in 600 seconds.

If the problem is confirmed to be the ISP i would need help with some additional information on how to lay out the words to make them understand the problem and what in there DHCP server configuration might be wrong.

Regards,

UrbanSk

Krakke · Apr 2, 2007, 8:33 AM

The issue with telia is that their dhcp dont answer all the time, if you got an D-Link DI-604 and the dhcp dont reply the DI-604 will release the ip, there for the short write in pfsense/freebsd?

snadde · Apr 13, 2007, 12:54 PM

I have exactly the same problem with telia.

The problem is with the configuration of the new equipment in the telestations. (Adsl 2+ ip based) The old equipment (up to 8Mbit, atm based) works fine.

The problem startet for me when I upgraded from 8 to 24 Mbit.

The problem as I see it is that the DHCP server stops answering at a certain time. It just doesn't answer. Then at last dhclient sends out a broadcast and another DHCP server answers with an IP. This never worked out for me so I switched back to the old system with only 8 Mbit… Here a log over what happens:

Jun 15 19:38:20 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:38:20 asterisk1 dhclient: DHCPACK from 62.20.251.18
Jun 15 19:38:20 asterisk1 dhclient: bound to 81.233.XXX.XXX -- renewal in 566 seconds.
Jun 15 19:47:46 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:48:22 asterisk1 last message repeated 4 times
Jun 15 19:48:57 asterisk1 last message repeated 2 times
Jun 15 19:49:25 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:50:05 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:51:44 asterisk1 last message repeated 2 times
Jun 15 19:53:57 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:54:40 asterisk1 dhclient: DHCPREQUEST on eth0 to 62.20.251.18 port 67
Jun 15 19:55:32 asterisk1 last message repeated 2 times
Jun 15 19:56:28 asterisk1 dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Jun 15 19:56:28 asterisk1 dhclient: DHCPACK from 81.232.98.1
Jun 15 19:56:28 asterisk1 dhclient: bound to 81.233.XXX.XXX -- renewal in 527 seconds.

Clearly at 19:47:46 the server at 62.20.251.18 stops answering requests. Then finally at 19:56:28 a broadcast is sent out and 81.232.98.1 answers with an IP... During these periods internet does not work.

I guess it would work fine if the requests were send as broadcasts all the time. Is there a possibility to make dhclient broadcast all requests instead of sending them to the specific dhcpserver?

cmb · Apr 13, 2007, 4:46 PM

It should fall back to a broadcast before it drops the previous IP, per the DHCP RFC. If it's still not doing that, we still have a problem.

snadde · Apr 14, 2007, 8:11 PM

I got a suggestion on another forum where I brought up this problem. Somebody had the same problem as I did and he solved it by rejecting the offers from one of the dhcp servers. In my case it would probably be the one that stops responding.
This is done by putting following code into dhclient.conf

reject <dhcpserver-ip-adress>;

The reject statement causes the DHCP client to reject offers from
servers who use the specified address as a server identifier.
This can be used to avoid being configured by rogue or misconfig-
ured DHCP servers, although it should be a last resort - better
to track down the bad DHCP server and fix it.

I have no possibility to verify or even test this suggestion since I'm no longer hooked up to the service where I experienced the problems. Bud if somebody tests this and verifies that it works, please write here and I'll be happy to upgrade to the higher speed again (:</dhcpserver-ip-adress>