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

Krakke

Tried that, and 1.0.1-SNAPSHOT-02-14-2007

Feb 14 20:32:46 dhclient[256]: exiting.
Feb 14 20:32:46 dhclient[256]: exiting.
Feb 14 20:32:46 dhclient[256]: short write: wanted 21 got 0 bytes
Feb 14 20:32:46 dhclient[256]: short write: wanted 21 got 0 bytes
Feb 14 20:32:46 dhclient[256]: DHCPACK from 172.21.249.50
Feb 14 20:32:46 dhclient[256]: DHCPREQUEST on fxp0 to 172.21.249.50 port 67
Feb 14 20:32:37 dhcpd: uid lease 192.168.1.245 for client 00:07:e9:b0:d6:26 is duplicate on 192.168.1/24

yoda715

We've established that dhclient is terminating prematurely for some reason. We're working hard to nail this down. Trouble is I'm the only developer experiencing this issue, but we are working on it.

freax

Hi.

My connection failed again but the logs went away during my lunch.
Is not possible to fetch old logs ?

I deactivated the firewall interface and then activated again and everything works.

yoda715

Everyone please update to the latest snapshot and see if that solves your disconnects.

http://snapshots.pfsense.com/FreeBSD6/RELENG_1/updates/

sullrich

@sdale:

Everyone please update to the latest snapshot and see if that solves your disconnects.

http://snapshots.pfsense.com/FreeBSD6/RELENG_1/updates/

What has changed that would fix it?

yoda715

Bill's patch. I'm running 2-14 and I haven't had an issue yet. Wondering if anyone else will with the new snapshot.

Selective

Sorry, no luck =(
Snapshot 02-14-2007:

–---------------------

Feb 18 11:59:18 dhclient[271]: exiting.
Feb 18 11:59:18 dhclient[271]: exiting.
Feb 18 11:59:18 dhclient[271]: short write: wanted 21 got 0 bytes
Feb 18 11:59:18 dhclient[271]: short write: wanted 21 got 0 bytes
Feb 18 11:59:18 dhclient[271]: DHCPACK from 90.224.168.1
Feb 18 11:59:18 dhclient[271]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 18 11:58:37 last message repeated 5 times
Feb 18 11:54:02 last message repeated 3 times
Feb 18 11:52:00 last message repeated 3 times
Feb 18 11:51:28 dhclient[271]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 18 11:41:51 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 18 11:41:51 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 18 11:41:51 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 18 11:41:50 check_reload_status: reloading filter
Feb 18 11:41:44 check_reload_status: updating dyndns
Feb 18 11:41:41 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 18 11:41:41 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 18 11:41:41 php: : FTP proxy disabled for interface LAN - ignoring.

sullrich

@Selective:

Sorry, no luck =(
Snapshot 02-14-2007:

–---------------------

Feb 18 11:59:18 dhclient[271]: exiting.
Feb 18 11:59:18 dhclient[271]: exiting.
Feb 18 11:59:18 dhclient[271]: short write: wanted 21 got 0 bytes
Feb 18 11:59:18 dhclient[271]: short write: wanted 21 got 0 bytes
Feb 18 11:59:18 dhclient[271]: DHCPACK from 90.224.168.1
Feb 18 11:59:18 dhclient[271]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 18 11:58:37 last message repeated 5 times
Feb 18 11:54:02 last message repeated 3 times
Feb 18 11:52:00 last message repeated 3 times
Feb 18 11:51:28 dhclient[271]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 18 11:41:51 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 18 11:41:51 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 18 11:41:51 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 18 11:41:50 check_reload_status: reloading filter
Feb 18 11:41:44 check_reload_status: updating dyndns
Feb 18 11:41:41 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 18 11:41:41 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 18 11:41:41 php: : FTP proxy disabled for interface LAN - ignoring.

Do you see anything in the filter logs showing blocked packets around this time?

Also, anyone having this problem, please run this from a shell:

fetch -o /etc/inc http://www.pfsense.com/~sullrich/filter.inc

Selective

no, i have not seen any blocked packets that could have something to do with this, but i am one of those
who are affected by the "promiscuous mode disabled", and therefore my firwall logs stops after a while.

isn´t there a way to catch the dhclient message and "restart" dhclient when its terminating, just as a workaround until you pinned down the problem ?

sullrich

We already have code to detect this but it doesnt appear to be working.

sullrich

Good news!

I was able to replicate this problem thanks to sdale and Vescovo.

Vescovo had the final fix and it has been commited. Please upgrade to a snapshot about an hour from this message.

yoda715

@sullrich:

Good news!

I was able to replicate this problem thanks to sdale and Vescovo.

Vescovo had the final fix and it has been commited. Please upgrade to a snapshot about an hour from this message.

I think you forgot to wave your magic voodoo wand, problem still exists ;). I think the problem lies in the rc.newwanip not catching the interface being assigned 0.0.0.0 IP address.

Selective

i did a workaround for that problem a couple of months ago:

rc.newwanip:
–---------------------------
if($curwanip == "0.0.0.0") {
log_error("Failed to update WAN IP, restarting dhclient.");
exec("dhclient {$interface_real}");
/* die now, dhclient will kick off rc.newwanip again? */
exit;
}

freax

Is not the real deal but if you disconnect the cable and connect it again you won't have link.
I have both ends with fixed ip (the router and firewall interface) and it should have link again like it should.

Like I said, i think it's a good way to debug whenever you want. Tests always available.

Sorry if i'm wrong.

Krakke

Tried this "fetch -o /etc/inc http://www.pfsense.com/~sullrich/filter.inc"

Now i have to reinstall pfsense :'(

sullrich

I have added a workaround and verified that it does indeed seem to work.

Update to the latest snapshot at least an hour from now. Currently 11:46PM EST.

Selective

im sorry to say this but, the new snapshot (02-18) is not working :(
–------------------------------

Feb 20 23:40:20 php: : rc.newwanip working with IP address 0.0.0.0 wan rl0.
Feb 20 23:40:20 php: : Informational: rc.newwanip is starting rl0.
Feb 20 23:40:19 dhclient: exit_with_hooks()
Feb 20 23:40:19 dhclient: PREINIT
Feb 20 23:40:19 dhclient: netstat
Feb 20 23:40:19 dhclient[21934]: DHCPOFFER from 90.224.168.1
Feb 20 23:40:19 dhclient[21934]: DHCPDISCOVER on rl0 to 255.255.255.255 port 67 interval 8
Feb 20 23:40:19 dhclient: exit_with_hooks()
Feb 20 23:40:19 check_reload_status: rc.newwanip starting
Feb 20 23:40:19 dhclient: PREINIT
Feb 20 23:40:19 dhclient: netstat
Feb 20 23:40:19 dhclient: exit_with_hooks()
Feb 20 23:40:18 dhclient: Deleting old routes
Feb 20 23:40:18 dhclient: EXPIRE FAIL
Feb 20 23:40:18 dhclient: netstat
Feb 20 23:40:18 dhclient: exit_with_hooks()
Feb 20 23:40:18 dhclient: PREINIT
Feb 20 23:40:18 dhclient: netstat
Feb 20 23:18:20 dhclient[280]: exiting.
Feb 20 23:18:20 dhclient[280]: exiting.
Feb 20 23:18:20 dhclient[280]: short write: wanted 21 got 0 bytes
Feb 20 23:18:20 dhclient[280]: short write: wanted 21 got 0 bytes
Feb 20 23:18:20 dhclient[280]: DHCPACK from 90.224.168.1
Feb 20 23:18:20 dhclient[280]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 20 23:16:07 last message repeated 6 times
Feb 20 23:12:37 last message repeated 7 times
Feb 20 23:10:43 last message repeated 4 times
Feb 20 23:10:13 dhclient[280]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 20 23:00:37 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 20 23:00:37 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 20 23:00:37 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 20 23:00:36 check_reload_status: reloading filter
Feb 20 23:00:30 check_reload_status: updating dyndns
Feb 20 23:00:27 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 20 23:00:27 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 20 23:00:27 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 20 23:00:23 check_reload_status: reloading filter
Feb 20 23:00:23 php: : Configuring slbd
Feb 20 23:00:23 php: : Resyncing configuration for all packages.
Feb 20 23:00:19 php: : Creating rrd update script

sullrich

I really don't see how it could not work.

Run this from a shell:

cat /sbin/dhclient | grep reload

What does the results say?

Selective

it does not say anything:
–----------------------------

Enter an option: 8

cat /sbin/dhclient | grep reload

Binary file (standard input) matches

sullrich

Can someone else please test? This absolutely works for me after 20 hours when normally it would break in 30 minutes…

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

rc.newwanip: –--------------------------- if($curwanip == "0.0.0.0") { log_error("Failed to update WAN IP, restarting dhclient."); exec("dhclient {$interface_real}"); /* die now, dhclient will kick off rc.newwanip again? */ exit; }

cat /sbin/dhclient | grep reload

cat /sbin/dhclient | grep reload

rc.newwanip:
–---------------------------
if($curwanip == "0.0.0.0") {
log_error("Failed to update WAN IP, restarting dhclient.");
exec("dhclient {$interface_real}");
/* die now, dhclient will kick off rc.newwanip again? */
exit;
}