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

freax · Feb 6, 2007, 10:16 AM

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

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 · Feb 6, 2007, 7:58 PM

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

Thanks!

freax · Feb 6, 2007, 8:10 PM

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

sullrich · Feb 6, 2007, 8:10 PM

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

freax · Feb 6, 2007, 8:12 PM

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

freax · Feb 6, 2007, 8:16 PM

It's there now. Thanks.

sullrich · Feb 6, 2007, 8:16 PM

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

freax · Feb 6, 2007, 8:31 PM

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 · Feb 6, 2007, 9:06 PM

@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 · Feb 7, 2007, 3:44 PM

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 · Feb 9, 2007, 6:09 PM

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

yoda715 · Feb 12, 2007, 6:20 PM

I'm experiencing this as well now. Updated to the 2-09 snapshot and still not working properly.

sullrich · Feb 12, 2007, 6:25 PM

Considering that none of the other devs can reproduce this, maybe you can help us nail this down.

yoda715 · Feb 12, 2007, 6:39 PM

Aye, Im trying. Looks like dhclient is trying to renew before lease expires. It's throwing everything out of wack. Dyndns, snort, WAN access to my box. Trying to determine pattern.

Krakke · Feb 13, 2007, 8:33 AM

I like what you guys are doing ;D this is from my pfbox, ISP BBB(Bredbandsbolaget) Sweden 100/10 mbit

1.0.1-SNAPSHOT-02-09-2007

Feb 13 08:14:21 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 85.226.176.x.
Feb 13 08:14:18 php: : Informational: rc.newwanip is starting.
Feb 13 08:14:17 check_reload_status: rc.newwanip starting
Feb 13 08:14:15 dhclient[67394]: bound to 85.226.176.x – renewal in 1800 seconds.
Feb 13 08:14:14 dhclient[67394]: DHCPACK from 172.21.249.50
Feb 13 08:14:14 dhclient[67394]: DHCPREQUEST on fxp0 to 172.21.249.50 port 67
Feb 13 07:44:24 dnsmasq[456]: using nameserver 195.54.122.198#53
Feb 13 07:44:24 dnsmasq[456]: using nameserver 195.54.122.200#53
Feb 13 07:44:24 dnsmasq[456]: using nameserver 195.54.122.199#53
Feb 13 07:44:24 dnsmasq[456]: using nameserver 81.26.227.3#53
Feb 13 07:44:24 dnsmasq[456]: reading /etc/resolv.conf
Feb 13 07:44:24 check_reload_status: updating dyndns
Feb 13 07:44:22 check_reload_status: reloading filter
Feb 13 07:44:21 php: : Configuring slbd
Feb 13 07:44:21 php: : Resyncing configuration for all packages.
Feb 13 07:44:20 php: : Creating rrd update script
Feb 13 07:44:20 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 85.226.176.x.
Feb 13 07:44:18 php: : Informational: rc.newwanip is starting.
Feb 13 07:44:17 check_reload_status: rc.newwanip starting
Feb 13 07:44:14 dhclient[67314]: bound to 85.226.176.x – renewal in 1800 seconds.
Feb 13 07:44:14 dhclient: /sbin/route add default 85.226.176.1
Feb 13 07:44:14 dhclient: New Routers (fxp0): 85.226.176.1
Feb 13 07:44:14 dhclient: New Broadcast Address (fxp0): 85.226.176.255
Feb 13 07:44:14 dhclient: New Subnet Mask (fxp0): 255.255.255.0
Feb 13 07:44:14 dhclient: New IP Address (fxp0): 85.226.176.x
Feb 13 07:44:14 dhclient[67314]: DHCPACK from 85.226.176.3
Feb 13 07:44:14 dhclient[67314]: DHCPREQUEST on fxp0 to 255.255.255.255 port 67
Feb 13 07:44:12 dhclient[67314]: DHCPOFFER from 85.226.176.3
Feb 13 07:44:12 dhclient[67314]: DHCPDISCOVER on fxp0 to 255.255.255.255 port 67 interval 7
-Renew-
Feb 13 00:41:09 dhclient[248]: exiting.
Feb 13 00:41:09 dhclient[248]: exiting.
Feb 13 00:41:09 dhclient[248]: short write: wanted 21 got 0 bytes
Feb 13 00:41:09 dhclient[248]: short write: wanted 21 got 0 bytes
Feb 13 00:41:09 dhclient[248]: DHCPACK from 172.21.249.50
Feb 13 00:41:09 dhclient[248]: DHCPREQUEST on fxp0 to 172.21.249.50 port 67
Feb 13 00:11:32 dnsmasq[456]: using nameserver 195.54.122.199#53
Feb 13 00:11:32 dnsmasq[456]: using nameserver 81.26.227.3#53
Feb 13 00:11:32 dnsmasq[456]: using nameserver 195.54.122.204#53
Feb 13 00:11:32 dnsmasq[456]: using nameserver 195.54.122.198#53
Feb 13 00:11:32 dnsmasq[456]: reading /etc/resolv.conf
Feb 13 00:11:19 check_reload_status: updating dyndns
Feb 13 00:11:16 check_reload_status: reloading filter
Feb 13 00:11:16 php: : Configuring slbd
Feb 13 00:11:16 php: : Resyncing configuration for all packages.
Feb 13 00:11:15 php: : Creating rrd update script
Feb 13 00:11:15 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 85.226.176.x.
Feb 13 00:11:12 php: : Informational: rc.newwanip is starting.
Feb 13 00:11:12 check_reload_status: rc.newwanip starting
Feb 13 00:11:10 dhclient[248]: bound to 85.226.176.x – renewal in 1800 seconds.
Feb 13 00:11:09 dhclient[248]: DHCPACK from 172.21.249.50
Feb 13 00:11:09 dhclient[248]: DHCPREQUEST on fxp0 to 172.21.249.50 port 67
Feb 13 00:01:45 dnsmasq[456]: using nameserver 195.54.122.199#53
Feb 13 00:01:45 dnsmasq[456]: using nameserver 81.26.227.3#53
Feb 13 00:01:45 dnsmasq[456]: using nameserver 195.54.122.204#53
Feb 13 00:01:45 dnsmasq[456]: using nameserver 195.54.122.198#53
Feb 13 00:01:45 dnsmasq[456]: reading /etc/resolv.conf
Feb 12 23:41:18 check_reload_status: updating dyndns
Feb 12 23:41:15 check_reload_status: reloading filter
Feb 12 23:41:15 php: : Configuring slbd
Feb 12 23:41:15 php: : Resyncing configuration for all packages.
Feb 12 23:41:14 php: : Creating rrd update script
Feb 12 23:41:14 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 85.226.176.x.
Feb 12 23:41:12 kernel: pflog0: promiscuous mode disabled
Feb 12 23:41:12 php: : Informational: rc.newwanip is starting.
Feb 12 23:41:11 check_reload_status: rc.newwanip starting
Feb 12 23:41:09 dhclient[248]: bound to 85.226.176.x – renewal in 1800 seconds.
Feb 12 23:41:09 dhclient[248]: DHCPACK from 172.21.249.50
Feb 12 23:41:09 dhclient[248]: DHCPREQUEST on fxp0 to 172.21.249.50 port 67

jmorey · Feb 13, 2007, 7:34 PM

Since I started this thread I guess I should mention that I'm no longer having the problem. The problem went away but I'm still running a stock 1.0.1 load. Thinking more and more the root cause was my service provider…

yoda715 · Feb 13, 2007, 9:47 PM

Everyone that is experiencing this problem, are you running miniupnpd on any interface? It seems to be that when I run upnp I experience this problem. Im running more test to confirm.

Feb 13 16:29:51 last message repeated 160 times
Feb 13 16:19:51 last message repeated 160 times
Feb 13 16:09:51 last message repeated 160 times
Feb 13 15:59:51 last message repeated 160 times
Feb 13 15:49:51 last message repeated 160 times
Feb 13 15:39:51 last message repeated 160 times
Feb 13 15:29:51 last message repeated 160 times
Feb 13 15:19:51 last message repeated 160 times
Feb 13 15:09:51 last message repeated 160 times
Feb 13 14:59:51 last message repeated 160 times
Feb 13 14:49:51 last message repeated 160 times
Feb 13 14:39:51 last message repeated 160 times
Feb 13 14:29:51 last message repeated 160 times
Feb 13 14:19:51 last message repeated 167 times
Feb 13 14:09:51 last message repeated 161 times
Feb 13 13:59:21 last message repeated 160 times
Feb 13 13:49:21 last message repeated 32 times
Feb 13 13:47:21 last message repeated 15 times
Feb 13 13:46:51 miniupnpd[20009]: sendto(udp_notify): No buffer space available
Feb 13 13:46:43 dhclient[272]: exiting.
Feb 13 13:46:43 dhclient[272]: exiting.
Feb 13 13:46:43 dhclient[272]: short write: wanted 21 got 0 bytes
Feb 13 13:46:43 dhclient[272]: short write: wanted 21 got 0 bytes
Feb 13 13:46:21 last message repeated 95 times
Feb 13 13:46:43 dhclient[272]: DHCPACK from 68.87.68.13
Feb 13 13:46:43 dhclient[272]: DHCPREQUEST on sis0 to 68.87.68.13 port 67
Feb 13 13:40:51 last message repeated 161 times
Feb 13 13:32:03 dnsmasq[642]: using nameserver 68.87.68.162#53
Feb 13 13:32:03 dnsmasq[642]: using nameserver 68.87.74.162#53
Feb 13 13:32:03 dnsmasq[642]: reading /etc/resolv.conf
Feb 13 13:30:21 last message repeated 167 times
Feb 13 13:20:21 last message repeated 33 times
Feb 13 13:17:51 last message repeated 15 times
Feb 13 13:17:21 miniupnpd[20009]: sendto(udp_notify): No buffer space available

Selective · Feb 13, 2007, 9:55 PM

No, not running any extras at all, everything is clean and simple !

sullrich · Feb 14, 2007, 5:43 AM

Everyone having this problem, please try this from a shell:

fetch -o /etc/ http://www.pfsense.com/~sullrich/devd.conf ; killall devd ; devd

Krakke · Feb 14, 2007, 9:30 PM

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