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

sullrich

Check your gmail account freax … I am working on this issue now and need your help. I cannot guarantee when I'll have time or interest to work on it again so right now is your chance to get it solved!

sullrich

Please test the latest snapshot if you are still having problems and post the logs. I have added some debugging information.

Selective

im using snapshot 02-02 and it still dosn´t work:

Feb 3 00:46:20 dhclient[275]: exiting.
Feb 3 00:46:20 dhclient[275]: exiting.
Feb 3 00:46:20 dhclient[275]: short write: wanted 21 got 0 bytes
Feb 3 00:46:20 dhclient[275]: short write: wanted 21 got 0 bytes
Feb 3 00:46:20 dhclient[275]: DHCPACK from 90.224.168.1
Feb 3 00:46:20 dhclient[275]: DHCPREQUEST on rl0 to 255.255.255.255 port 67

freax

Hi again.

I'm at 180 km from the firewall so I will test it monday.

Thanks.

TheOtherBastard

I've been experiencing this problem lately and it still has not been resolved for myself either.

ISP: ZoomInternet

I'm not sure my exact snapshot, but it was most recently updated on Jan29.

Any info that I can provide to help get this resolved I am more than willing to give.

sullrich

@TheOtherBastard:

I've been experiencing this problem lately and it still has not been resolved for myself either.

ISP: ZoomInternet

I'm not sure my exact snapshot, but it was most recently updated on Jan29.

Any info that I can provide to help get this resolved I am more than willing to give.

Please update to a recent snapshot like I asked everyone else to do.

sullrich

Anyone have an update? Or is the problem finally fixed with recent snapshots?

Selective

do you mean snapshot 02-02 ?? if you do, the problem is not fixed =(
still ending up with "short write: wanted 21 got 0 bytes"

sullrich

Yes, the updated snapshot as of a day or so.

Please provide the entire log file.. As much detail as possible. You can X out IP addresses but I need to see the chain of events from before and after this happens.

Also, for the record, who uses PPPOE and who has just a regular DHCP WAN?

freax

I've updated but still now it didn't stop. Maybe I can turn off then on the router.

I have 2 links:

fxp0 that is our pppoe wan that is used for servers and DMZ;
vr0 which is in opt1 that serves our worksations; This is connected to a router trought a diffrent ip.

I think I had 2 different problems:

pppoe (fxp0) went down from time to time and I think it was solved with some latest update. This was the worst because sometimes we dind't have vpn at weekends. I think it's solved.
now I still have the last problem which the workstations don't have internet with some dhcp problem. There isn't dhcp activated neither on router or firewall.

[]'s

@sullrich:

Yes, the updated snapshot as of a day or so.

Please provide the entire log file.. As much detail as possible. You can X out IP addresses but I need to see the chain of events from before and after this happens.

Also, for the record, who uses PPPOE and who has just a regular DHCP WAN?

sullrich

I have made some more changes for debugging. Please test todays snapshot.

Thanks!

freax

Confirm me that its the pfSense-Full-Update-1.0.1-SNAPSHOT-02-02-2007.tgz dated from today please.

sullrich

No, todays date is the 6th. Images are still building. Check back in an hour.

freax

It's from http://snapshots.pfsense.com/FreeBSD6/RELENG_1/updates/ ? Right ?
There isn't any from today.

freax

It's there now. Thanks.

sullrich

http://snapshots.pfsense.com/FreeBSD6/RELENG_1/updates/pfSense-Full-Update-1.0.1-SNAPSHOT-02-06-2007.tgz

freax

Hi again.

I did the update but i think I can simulate what's happening.

The firewall interface and router, both have fixed ip's so what I did was unplug then plug again for 2 seconds. Then, no Internet:

Feb 6 20:23:03 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 6 20:23:03 php: : Processing vr0 - start
Feb 6 20:23:03 php: : Arguments passed rc.linkup. 'vr0 start '
Feb 6 20:23:03 check_reload_status: rc.linkup starting
Feb 6 20:22:58 kernel: vr0: link state changed to UP
Feb 6 20:22:58 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 6 20:22:58 php: : Processing vr0 - stop
Feb 6 20:22:58 php: : Arguments passed rc.linkup. 'vr0 stop '
Feb 6 20:22:58 check_reload_status: rc.linkup starting
Feb 6 20:22:55 kernel: vr0: link state changed to DOWN
Feb 6 20:22:01 syslogd: kernel boot file is /boot/kernel/kernel

The same result before I think.

I will wait that this happens naturaly but this may help for now.

Thanks.

sullrich

@freax:

Hi again.

I did the update but i think I can simulate what's happening.

The firewall interface and router, both have fixed ip's so what I did was unplug then plug again for 2 seconds. Then, no Internet:

Feb 6 20:23:03 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 6 20:23:03 php: : Processing vr0 - start
Feb 6 20:23:03 php: : Arguments passed rc.linkup. 'vr0 start '
Feb 6 20:23:03 check_reload_status: rc.linkup starting
Feb 6 20:22:58 kernel: vr0: link state changed to UP
Feb 6 20:22:58 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 6 20:22:58 php: : Processing vr0 - stop
Feb 6 20:22:58 php: : Arguments passed rc.linkup. 'vr0 stop '
Feb 6 20:22:58 check_reload_status: rc.linkup starting
Feb 6 20:22:55 kernel: vr0: link state changed to DOWN
Feb 6 20:22:01 syslogd: kernel boot file is /boot/kernel/kernel

The same result before I think.

I will wait that this happens naturaly but this may help for now.

Thanks.

Thanks. Can you update with the latest snapshot and run that again? There appears to be some missing debugging that I added earlier today.

You may want to download the snapshot again to ensure that the code is present.

Thanks!!

Selective

Heres my log, from start to end, untouched.
Using regular Dhcp for my WAN:
–-------------------------------

Feb 7 12:53:54 dhclient[275]: exiting.
Feb 7 12:53:54 dhclient[275]: exiting.
Feb 7 12:53:54 dhclient[275]: short write: wanted 22 got 0 bytes
Feb 7 12:49:47 last message repeated 2 times
Feb 7 12:53:54 dhclient[275]: short write: wanted 22 got 0 bytes
Feb 7 12:46:23 last message repeated 2 times
Feb 7 12:44:28 last message repeated 3 times
Feb 7 12:43:53 dhclient[275]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 7 12:34:07 check_reload_status: updating dyndns
Feb 7 12:34:05 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 12:34:05 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 12:34:05 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 12:34:03 check_reload_status: reloading filter
Feb 7 12:34:02 php: : Configuring slbd
Feb 7 12:34:02 php: : Resyncing configuration for all packages.
Feb 7 12:33:58 php: : Creating rrd update script
Feb 7 12:33:58 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 90.224.168.54.
Feb 7 12:33:55 php: : Informational: rc.newwanip is starting.
Feb 7 12:33:54 check_reload_status: rc.newwanip starting
Feb 7 12:33:53 dhclient[275]: bound to 90.224.168.54 – renewal in 600 seconds.
Feb 7 12:33:53 dhclient[275]: DHCPACK from 90.224.168.1
Feb 7 12:33:53 dhclient[275]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 7 12:33:12 last message repeated 11 times
Feb 7 12:28:15 last message repeated 3 times
Feb 7 12:26:37 last message repeated 3 times
Feb 7 12:25:54 dhclient[275]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 7 12:16:15 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 12:16:15 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 12:16:15 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 12:16:14 check_reload_status: reloading filter
Feb 7 12:16:08 check_reload_status: updating dyndns
Feb 7 12:16:05 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 12:16:05 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 12:16:05 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 12:16:02 check_reload_status: reloading filter
Feb 7 12:16:02 php: : Configuring slbd
Feb 7 12:16:02 php: : Resyncing configuration for all packages.
Feb 7 12:15:59 php: : Creating rrd update script
Feb 7 12:15:58 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 90.224.168.54.
Feb 7 12:15:56 kernel: pflog0: promiscuous mode disabled
Feb 7 12:15:56 php: : Informational: rc.newwanip is starting.
Feb 7 12:15:55 check_reload_status: rc.newwanip starting
Feb 7 12:15:55 dhclient[275]: bound to 90.224.168.54 – renewal in 600 seconds.
Feb 7 12:15:54 dhclient[275]: DHCPACK from 90.224.168.1
Feb 7 12:15:54 dhclient[275]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 7 12:15:14 last message repeated 6 times
Feb 7 12:10:35 last message repeated 4 times
Feb 7 12:08:19 last message repeated 2 times
Feb 7 12:08:03 dhclient[275]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 7 11:58:26 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 11:58:26 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 11:58:26 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 11:58:25 check_reload_status: reloading filter
Feb 7 11:58:19 check_reload_status: updating dyndns
Feb 7 11:58:16 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 11:58:16 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 11:58:16 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 11:58:14 check_reload_status: reloading filter
Feb 7 11:58:14 php: : Configuring slbd
Feb 7 11:58:14 php: : Resyncing configuration for all packages.
Feb 7 11:58:09 php: : Creating rrd update script
Feb 7 11:58:08 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 90.224.168.54.
Feb 7 11:58:06 php: : Informational: rc.newwanip is starting.
Feb 7 11:58:05 check_reload_status: rc.newwanip starting
Feb 7 11:58:03 dhclient[275]: bound to 90.224.168.54 – renewal in 600 seconds.
Feb 7 11:58:03 dhclient[275]: DHCPACK from 90.224.168.1
Feb 7 11:58:03 dhclient[275]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 7 11:57:05 last message repeated 6 times
Feb 7 11:52:30 last message repeated 3 times
Feb 7 11:50:10 last message repeated 3 times
Feb 7 11:49:45 dhclient[275]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 7 11:40:11 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 11:40:11 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 11:40:11 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 11:40:10 check_reload_status: reloading filter
Feb 7 11:40:03 check_reload_status: updating dyndns
Feb 7 11:40:01 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 11:40:01 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 11:40:01 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 11:39:58 check_reload_status: reloading filter
Feb 7 11:39:57 php: : Configuring slbd
Feb 7 11:39:57 php: : Resyncing configuration for all packages.
Feb 7 11:39:54 php: : Creating rrd update script
Feb 7 11:39:54 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 90.224.168.54.
Feb 7 11:39:52 php: : Informational: rc.newwanip is starting.
Feb 7 11:39:50 check_reload_status: rc.newwanip starting
Feb 7 11:39:46 dhclient[275]: bound to 90.224.168.54 – renewal in 600 seconds.
Feb 7 11:39:45 dhclient[275]: DHCPACK from 90.224.168.1
Feb 7 11:39:45 dhclient[275]: DHCPREQUEST on rl0 to 255.255.255.255 port 67
Feb 7 11:39:01 last message repeated 10 times
Feb 7 11:34:02 last message repeated 4 times
Feb 7 11:32:17 last message repeated 5 times
Feb 7 11:31:38 dhclient[275]: DHCPREQUEST on rl0 to 213.67.15.234 port 67
Feb 7 11:25:13 check_reload_status: updating dyndns
Feb 7 11:25:10 php: : FTP proxy disabled for interface opt2 - ignoring.
Feb 7 11:25:10 php: : FTP proxy disabled for interface opt1 - ignoring.
Feb 7 11:25:10 php: : FTP proxy disabled for interface LAN - ignoring.
Feb 7 11:25:08 check_reload_status: reloading filter
Feb 7 11:25:07 php: : Configuring slbd
Feb 7 11:25:06 php: : Resyncing configuration for all packages.

freax

With 08/02/2007 snapshot.
I unplugged the cable and then plugged it again.
I will post soon when it naturaly fails.

Feb 9 18:04:41 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 9 18:04:41 php: : Processing vr0 - start
Feb 9 18:04:41 php: : Hotplug event detected for vr0 but ignoring since interface is not set for DHCP
Feb 9 18:04:41 php: : Processing vr0 - stop
Feb 9 18:04:41 php: : Arguments passed rc.linkup. 'vr0 stop vr0 start '
Feb 9 18:04:41 check_reload_status: rc.linkup starting
Feb 9 18:04:41 kernel: vr0: link state changed to UP
Feb 9 18:04:39 kernel: vr0: link state changed to DOWN
Feb 9 18:04:25 syslogd: kernel boot file is /boot/kernel/kernel